1. 程式人生 > >【轉】IIS日誌-網站運維的好幫手

【轉】IIS日誌-網站運維的好幫手

alt 修改 分享 雙擊 字段名 localtime 簡單 排序 利用

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

與開發階段不同的,運維階段不可能讓你去調試程序,發現各類問題, 我們只能通過各種系統日誌來分析網站的運行狀況, 對於部署在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";

        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);

        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);
        }

        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,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響應也是一個頁面響應,而且它們也會占用網絡傳輸時間, 尤其是這類請求不能緩存,它會一直出現,浪費網絡資源。

如果你希望在開發階段就能輕易的發現404錯誤,可以參考我的博客:程序在發布前就應該發現的一些錯誤


如果發現有大量的304請求也應該仔細分析:
1. 是由於ASP.NET緩存響應而產生的304請求嗎?
2. 還是請求靜態資源文件時產生的304請求?
如果是後者,則有可能與瀏覽器的設置有關,也有可能與IIS設置有關。

IIS有個【啟用內容過期】功能,可用來在輸出響應時設置緩存頭,減少請求數量。
此功能對靜態文件有用,ASP.NET處理的結果則不受影響。
具體設置方法可參考:不修改代碼就能優化ASP.NET網站性能的一些方法


我們可以用這樣的查詢來分析頁面的加載頻率:

select top 20 csUriStem, count(*) AS [count],
    avg(timeTaken) AS avg_timeTaken, max(timeTaken) AS max_timeTaken
from MyMVC_WebLog with(nolock)
where csUriStem like ‘/Pages/%‘
group by csUriStem
order by 2 desc

如果發現有大量的重復請求,也需要再仔細分析:
1. 請求的響應內容是否隨著不同的參數而各不相同?
2. 請求的URL是固定的,響應內容也是極少變化的。
如果是後者,則可以考慮使用頁面緩存功能。例如:ASP.NET的OutputCache

我的博客不修改代碼就能優化ASP.NET網站性能的一些方法 介紹了一種不用修改代碼就能緩存請求的功能,如果需要,可以試試。

回到頂部

程序架構對IIS日誌分析過程的影響

前面我介紹了一些分析IIS日誌的方法,這些方法的使用都離不開查詢。 絕大多數時候,我們需要在查詢中輸出URL信息(cs-uri-stem)並依據它們分組來統計, 因此,合理的設計URL會給後期的統計帶來方便, 也能得到更準確的統計結果。 一個極端的反例是:采用WebForms默認的開發方式,頁面加載以及每個按鈕的提交都是同一個URL,你會發現很難統計用戶的每個操作花了多少時間。

怎樣的URL設計才能滿足統計需要呢?
我認為:每個用戶操作(頁面顯示或者提交)都應該有一個URL與之對應,且不同的URL能反映不同的操作。
另外還建議:不同的用戶操作能在URL中清楚的區分開,這樣能方便做更多的統計(例如:頁面加載,AJAX請求,報表顯示)。


雖然我們可以用timeTaken來做性能統計,然而,當你在程序中大量使用frameset或者iframe時, 你將難以統計某個頁面(包含iframe的頁面)加載到底花了多長時間。 因為整個頁面被分成了多個請求,它們在IIS日誌中並不是連續的,你無法準確地按用戶請求來統計。 例如:a1.aspx用iframe的方式嵌入了b1.aspx, b2.aspx, b3.aspx,當你統計a1.aspx的加載時間時, 你得到的結果永遠和用戶感受的情況不一樣,因為a1.aspx的timeTaken並不包含b1.aspx, b2.aspx, b3.aspx這三個請求的timeTaken!

因此,如果你希望利用IIS日誌來分析程序性能,那麽iframe就不要再使用了。

轉載自:http://www.cnblogs.com/fish-li/p/3139366.html

【轉】IIS日誌-網站運維的好幫手