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

        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就不要再使用了。