網站運維工具使用iis日志分析工具分析iis日志(iis日志的配置)

點評:我們隻能通過各種系統日志來分析網站的運行狀況,對於部署在IIS上的網站來說,IIS日志提供瞭最有價值的信息,我們可以通過它來分析網站的響應情況,來判斷網站是否有性能問題,或者存在哪些需要改進的地方

對於一個需要長期維護的網站來說,如何讓網站長久穩定運行是件很有意義的事情。有些在開發階段沒有暴露的問題很有可能就在運維階段出現瞭,這也是很正常的。還有些時候,我們希望不斷地優化網站,讓網站更快速的響應用戶請求,這些事情都發生在開發之後的運維階段。

與開發階段不同的,運維階段不可能讓你去調試程序,發現各類問題,我們隻能通過各種系統日志來分析網站的運行狀況,對於部署在IIS上的網站來說,IIS日志提供瞭最有價值的信息,我們可以通過它來分析網站的響應情況,來判斷網站是否有性能問題,或者存在哪些需要改進的地方。

IIS日志包含瞭哪些信息

我前面說到【IIS日志提供瞭最有價值的信息】,這些信息有哪些呢?看看這個截圖吧:

這裡面記錄瞭:
1. 請求發生在什麼時刻,
2. 哪個客戶端IP訪問瞭服務端IP的哪個端口,
3. 客戶端工具是什麼類型,什麼版本,
4. 請求的URL以及查詢字符串參數是什麼,
5. 請求的方式是GET還是POST,
6. 請求的處理結果是什麼樣的:HTTP狀態碼,以及操作系統底層的狀態碼,
7. 請求過程中,客戶端上傳瞭多少數據,服務端發送瞭多少數據,
8. 請求總共占用服務器多長時間、等等。

這些信息在分析時有什麼用途,我後面再說。先對它有個印象就可以瞭。



IIS日志的配置

默認情況下,IIS會產生日志文件,不過,還是有些參數值得我們關註。IIS的設置界面如下(本文以 IIS 8 的界面為例)。

在IIS管理器中,選擇某個網站,雙擊【日志】圖標,請參考下圖:

此時(主要部分)界面如下:

在截圖中,日志的創建方式是每天產生一個新文件,按日期來生成文件名(這是默認值)。
說明:IIS使用UTC時間,所以我勾選瞭最下面的復選框,告訴IIS用本地時間來生成文件名。

點擊【選擇字段】按鈕,將出現以下對話框:

註意:【發送的字段數】和【接收的字節數】默認是沒有選擇的。建議勾選它們。
至於其它字段,你可以根據需要來決定是否要勾選它們。

如何分析IIS日志

如果你按照我前面介紹的方法設置瞭IIS日志參數,那麼IIS在處理請求後(的一段時間之後),會生成IIS日志。
我們可以在【日志界面】的右邊區域【操作】中點擊【查看日志文件】快速定位到IIS日志的根目錄,然後到目錄中尋找相應的日志文件(默認會根據應用程序池序號來區分目錄)。

比如:我找到瞭我需要的日志:

這個文件一大堆密密麻麻的字符,現在我該如何分析它呢?

有個叫 Log Parser 的工具就可以專門解析IIS日志,我們可以用它來查看日志中的信息。
比如我可以運行下面的命令行(說明:為瞭不影響頁面寬度我將命令文本換行瞭):

復制代碼代碼如下:
“C:\Program Files\Log Parser 2.2\LogParser.exe” -i:IISW3C -o:DATAGRID
“SELECT c-ip,cs-method,s-port,cs-uri-stem,sc-status,sc-win32-status,
sc-bytes,cs-bytes,time-taken FROM u_ex130615.log”

現在就可以以表格形式來閱讀IIS日志瞭:

說明:我不推薦用這種方法來分析IIS日志,原因有二點:
1. 慢:當日志文件稍大一點的時候,用它來分析就比較浪費時間瞭(尤其是需要多次統計時)。
2. 不方便:它支持的查詢語法不夠豐富,沒有像SQL Server針對數據表查詢那樣全面。

推薦的IIS日志分析方法

雖然Log Parser支持將解析的IIS日志以表格形式供人閱讀,但是有時候我們需要再做一些細致分析時,可能會按不同的方式進行【多次】查詢,對於這種需求,如果每次查詢都直接運行Log Parser,你會浪費很多時間。幸運的是,Log Parser支持將解析結果以多種格式導出(以下為幫助文檔截圖):

在此,我建議選擇輸出格式為 SQL 。
註意:這裡的SQL並不是指SQLSERVER,而是指所有提供ODBC訪問接口的數據庫。
我可以使用下面的命令將IIS日志導入到SQLSERVER中(說明:為瞭不影響頁面寬度我將命令文本換行瞭):

復制代碼代碼如下:
“C:\Program Files\Log Parser 2.2\logparser.exe”
“SELECT * FROM ‘D:\Temp\u_ex130615.log’ to MyMVC_WebLog” -i:IISW3C -o:SQL
-oConnString:”Driver={SQL Server};server=localhost\sqlexpress;database=MyTestDb;Integrated Security=SSPI”
-createtable:ON

導入完成後,我們就可以用熟悉的SQLSERVER來做各種查詢和統計分析瞭,例如下面的查詢:

復制代碼代碼如下:
SELECT cip,csmethod,sport,csuristem,scstatus,scwin32status,scbytes,csbytes,timetaken
FROM dbo.MyMVC_WebLog

如果如下:

註意:
1. IIS日志在將結果導出到SQLSERVER時,字段名中不符合標識符規范的字符將會刪除。
   例如:c-ip 會變成 cip, s-port 會變成 sport 。
2. IIS日志中記錄的時間是UTC時間,而且把日期和時間分開瞭,導出到SQLSERVER時,會生成二個字段:
   

date, time這二個字段看起來很不舒服,對吧?
我也很反感這個結果,下面來說說的二種解決方法:

1. 在SQLSERVER中增加一列,然後把UTC時間換成本地時區的時間,T-SQL腳本如下:

復制代碼代碼如下:
alter table MyMVC_WebLog add RequestTime datetime
go
update MyMVC_WebLog set RequestTime=dateadd(hh,8,convert(varchar(10),date,120)
+ ‘ ‘ + convert(varchar(13),time,114))

2. 直接在導出IIS日志時,把時間轉換過來,此時要修改命令:

復制代碼代碼如下:
“C:\Program Files\Log Parser 2.2\logparser.exe”
“SELECT TO_LOCALTIME(TO_TIMESTAMP(ADD(TO_STRING(date, ‘yyyy-MM-dd ‘), TO_STRING(time, ‘hh:mm:ss’)),
‘yyyy-MM-dd hh:mm:ss’)) AS RequestTime, * FROM ‘D:\Temp\u_ex130615.log’ to MyMVC_WebLog2″
-i:IISW3C -o:SQL
-oConnString:”Driver={SQL Server};server=localhost\sqlexpress;database=MyTestDb;Integrated Security=SSPI”
-createtable:ON

再看這三列:

復制代碼代碼如下:
select RequestTime, date, time from MyMVC_WebLog2

這樣處理後,你就可以直接把date, time這二列刪除瞭(你也可以在導出IIS日志時忽略它們,但要明確指出每個字段名)。

IIS日志中的UTC時間問題就說到這裡,但願每個人都懂瞭~~~~~~~~~~~

IIS日志中的異常記錄

IIS日志中記錄瞭每個請求的信息,包括正常的響應請求和有異常的請求。

這裡所說的【異常】與 .net framework 中的異常沒有關系。
對於一個ASP.NET程序來說,如果拋出一個未捕獲異常,會記錄到IIS日志中(500),但我所說的異常不僅限於此。

本文所說的異常可分為四個部分:
1. (ASP.NET)程序拋出的未捕獲異常,導致服務器產生500的響應輸出。
2. 404之類的請求資源不存在錯誤。
3. 大於500的服務器錯誤,例如:502,503
4. 系統錯誤或網絡傳輸錯誤。

前三類異常可以用下面的查詢獲得:

復制代碼代碼如下:
select scStatus, count(*) AS count, sum(timetaken * 1.0) /1000.0 AS sum_timetaken_second
from MyMVC_WebLog with(nolock)
group by scStatus
order by 3 desc

IIS日志中有一列:sc-win32-status ,它記錄瞭在處理請求過程中,發生的系統級別錯誤,例如網絡傳輸錯誤。
正常情況下,0 表示正常,出現非零值意味著出現瞭錯誤。我們可以這樣統計這類錯誤

復制代碼代碼如下:
declare @recCount bigint;
select @recCount = count(*) from MyMVC_WebLog with(nolock)
select scWin32Status, count(*) AS count, (count(*) * 100.0 / @recCount) AS [percent]
from MyMVC_WebLog with(nolock)
where scWin32Status > 0
group by scWin32Status
order by 2 desc

下表列出瞭比較常見的與網絡相關的錯誤及解釋:

scWin32Status 含義
64 客戶端連接已關閉(或者斷開)
121 傳輸超時
1236 本地網絡中斷

所有狀態碼都可以通過下面的命令來獲取對應的解釋:

D:\Temp>net helpmsg 64指定的網絡名不再可用。

關於scwin32status與scStatus,我還想補充說明一下:它們沒有關聯。
比如請求這個地址:http://www.abc.com/test.aspx
有可能scStatus=200,但scwin32status=64,此時表示ASP.NET已成功處理請求,但是IIS在發送響應結果時,客戶端的連接斷開瞭。
另一種情況是:scStatus=500,但scwin32status=0,此時表示,在處理請求過程中發生瞭未捕獲異常,但異常結果成功發送給客戶端。

再談 scwin32status=64

記得以前看到 scStatus=200,scwin32status=64 這種情況時很不理解,於是搜索瞭互聯網,各種答案都有,有的甚至說與網絡爬蟲有關。為瞭驗證各種答案,我做瞭一個試驗。我寫一個ashx文件,用它來模擬長時間的網絡傳輸,代碼如下:

復制代碼代碼如下:
public class Test_IIS_time_taken : IHttpHandler {

public void ProcessRequest (HttpContext context) {
context.Response.ContentType = “text/plain”;</p>
<p> System.Threading.Thread.Sleep(1000 * 2);

context.Response.Write(string.Format(“{0}, {1}\r\n”, “Start”, DateTime.Now));
context.Response.Flush();

System.Threading.Thread.Sleep(1000 * 2);</p>
<p> for( int i = 0; i < 20; i++ ) {
context.Response.Write(string.Format(“{0}, {1}\r\n”, i, DateTime.Now));
context.Response.Flush();
System.Threading.Thread.Sleep(1000 * 1);
}</p>
<p> context.Response.Write(“End”);
}

段代碼很簡單,我不想做過多的解釋,隻想說一句:我用Thread.Sleep與Response.Flush這二個方法來模擬一個長時間的持續發送過程。

我們可以在瀏覽器中看到這樣的輸出(顯示還沒有完全結束時我截圖瞭)

我把這個測試做瞭8次,隻有2次是全部顯示完成瞭,其餘6次我提前關閉瞭瀏覽器窗口。
然後,我們再來看IIS日志的內容:

根據IIS日志並結合我自己的操作可以發現:
1. 當我提前關閉瀏覽器窗口時,就會看到scStatus=200,scwin32status=64
2. 如果請求內容全部顯示完成,我就會看到scStatus=200,scwin32status=0
從這個試驗我們還可以發現:timeTaken 包含瞭網絡傳輸時間。

根據這個試驗的結果,你是否想過一個問題:
如果你的網站的IIS日志中出現瞭大量的scStatus=200,scwin32status=64,而且請求是由用戶的瀏覽器發起的。
這是什麼原因造成的呢?
我的【猜想】是:用戶在訪問這個網站時已經不願意再等待瞭,他們把瀏覽器窗口關掉瞭。
換句話說:可以從scwin32status=64的統計結果看出網站的響應速度是否能讓用戶滿意。

尋找性能問題

IIS日志中有一列叫:timeTaken,在IIS的界面中顯示瞭它的含義:所有時間。
這個所用時間的定義是:從服務端收到請求的第一個字節開始起,直到把所有響應內容發送出去為止的時間。
微軟的網站有對這個字段做過說明:http://support.microsoft.com/kb/944884

知道瞭timeTaken的定義後,我們就可以利用它來分析一些請求的處理時間,即性能分析。

例如,我想查看最慢的20個頁面的加載情況,可以這樣查詢:

select top 20 csuristem,scstatus,scwin32status,scbytes,csbytes,timetakenfrom dbo.MyMVC_WebLog with(nolock)where csUriStem like '/Pages/%'order by timeTaken desc

再或者我想再看看最慢的20個AJAX情況的響應情況,可以這樣查詢:

復制代碼代碼如下:
select top 20 csuristem,scstatus,scwin32status,scbytes,csbytes,timetaken
from dbo.MyMVC_WebLog with(nolock)
where csUriStem like ‘/Pages/%’
order by timeTaken desc

再或者我想再看看最慢的20個AJAX情況的響應情況,可以這樣查詢:

復制代碼代碼如下:
select top 20 csuristem,scstatus,scwin32status,scbytes,csbytes,timetaken
from dbo.MyMVC_WebLog with(nolock)
where csUriStem like ‘/ajax/%’
order by timeTaken desc

總之,尋找性能問題的方法就是:在查詢選擇timeTaken字段,並且用它做降序排序。

註意:scbytes,csbytes 這二個字段也是值得我們關註的:
1. csbytes如果過大,我們就要分析一下到底是不是因為表單包含瞭過多的無用數據,可否將表單拆分。
   csbytes變大還有一種可能:Cookie太大,但它會表現為很多請求的csbytes都偏大,因此容易區分。
2. scbytes如果過大,我們就要檢查頁面是否沒有分頁,或者可以考慮用按需加載的方式來實現。
典型的情況是:當大量使用ViewState時,這二個值都會變大。因此我們能通過IIS日志發現ViewState的濫用問題。
還有一種特殊情況是:上傳下載文件也會導致這二個數值變大,原因我就不解釋瞭。

scbytes,csbytes,不管是哪個數值很大,都會占用網絡傳輸時間,對於用戶來說,就需要更長的等待時間。

一下子說瞭三個字段,在尋找性能問題時,到底該參考哪個呢?
我認為:應該優先關註timeTaken,因為它的數值直接反映瞭用戶的等待時間(不包括前端渲染時間)。
如果timeTaken過大時,有必要檢查scbytes,csbytes是否也過大,
如果後二者也過大,那麼優化的方向就是減少數據傳輸量,否則表示是程序處理占用瞭大量的時間,應該考慮優化程序代碼。

尋找可改進的目標

除瞭可以從IIS日志中發現性能問題,還可以用它來尋找可改進的目標。
例如:
1. 有沒有404錯誤?
2. 是否存在大量的304請求?
3. 是否存在大量重復請求?

當發現有404響應時,我們應該分析產生404的原因:
1. 是用戶輸入錯誤的URL地址嗎?
2. 還是開發人員引用不存在的資源文件?
如果是後者,就應該盡快移除無效的引用,因為404響應也是一個頁面響應,而且它們也會占用網絡傳輸時間,尤其是這類請求不能緩存,它會一直出現,浪費網絡資源。

Leave a Reply

Your email address will not be published. Required fields are marked *