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

若是，您認爲閱讀這篇博客讓您有些收穫，不妨點擊一下右下角的【推薦】按鈕。
若是，您但願更容易地發現個人新博客，不妨點擊一下右下角的【關注 Fish Li】。
由於，個人寫做熱情也離不開您的確定支持。

感謝您的閱讀，若是您對個人博客所講述的內容有興趣，請繼續關注個人後續博客，我是Fish Li 。