網(wǎng)站運(yùn)維工具IIS日志的示例分析

網(wǎng)站運(yùn)維工具IIS日志的示例分析，相信很多沒有經(jīng)驗(yàn)的人對此束手無策，為此本文總結(jié)了問題出現(xiàn)的原因和解決方法，通過這篇文章希望你能解決這個問題。

對于一個需要長期維護(hù)的網(wǎng)站來說，如何讓網(wǎng)站長久穩(wěn)定運(yùn)行是件很有意義的事情。 有些在開發(fā)階段沒有暴露的問題很有可能就在運(yùn)維階段出現(xiàn)了，這也是很正常的。 還有些時候，我們希望不斷地優(yōu)化網(wǎng)站，讓網(wǎng)站更快速的響應(yīng)用戶請求， 這些事情都發(fā)生在開發(fā)之后的運(yùn)維階段。

與開發(fā)階段不同的，運(yùn)維階段不可能讓你去調(diào)試程序，發(fā)現(xiàn)各類問題， 我們只能通過各種系統(tǒng)日志來分析網(wǎng)站的運(yùn)行狀況， 對于部署在IIS上的網(wǎng)站來說，IIS日志提供了最有價值的信息，我們可以通過它來分析網(wǎng)站的響應(yīng)情況，來判斷網(wǎng)站是否有性能問題， 或者存在哪些需要改進(jìn)的地方。

IIS日志包含了哪些信息

我前面說到【IIS日志提供了最有價值的信息】，這些信息有哪些呢？看看這個截圖吧：

這里面記錄了：

1. 請求發(fā)生在什么時刻，

2. 哪個客戶端IP訪問了服務(wù)端IP的哪個端口，

3. 客戶端工具是什么類型，什么版本，

4. 請求的URL以及查詢字符串參數(shù)是什么，

5. 請求的方式是GET還是POST，

6. 請求的處理結(jié)果是什么樣的：HTTP狀態(tài)碼，以及操作系統(tǒng)底層的狀態(tài)碼，

7. 請求過程中，客戶端上傳了多少數(shù)據(jù)，服務(wù)端發(fā)送了多少數(shù)據(jù)，

8. 請求總共占用服務(wù)器多長時間、等等。

這些信息在分析時有什么用途，我后面再說。先對它有個印象就可以了。

IIS日志的配置

默認(rèn)情況下，IIS會產(chǎn)生日志文件，不過，還是有些參數(shù)值得我們關(guān)注。 IIS的設(shè)置界面如下（本文以 IIS 8 的界面為例）。

在IIS管理器中，選擇某個網(wǎng)站，雙擊【日志】圖標(biāo)，請參考下圖：

此時（主要部分）界面如下：

在截圖中，日志的創(chuàng)建方式是每天產(chǎn)生一個新文件，按日期來生成文件名（這是默認(rèn)值）。

說明：IIS使用UTC時間，所以我勾選了最下面的復(fù)選框，告訴IIS用本地時間來生成文件名。

點(diǎn)擊【選擇字段】按鈕，將出現(xiàn)以下對話框：

注意：【發(fā)送的字段數(shù)】和【接收的字節(jié)數(shù)】默認(rèn)是沒有選擇的。建議勾選它們。

至于其它字段，你可以根據(jù)需要來決定是否要勾選它們。

如何分析IIS日志？

如果你按照我前面介紹的方法設(shè)置了IIS日志參數(shù)，那么IIS在處理請求后（的一段時間之后），會生成IIS日志。

我們可以在【日志界面】的右邊區(qū)域【操作】中點(diǎn)擊【查看日志文件】快速定位到IIS日志的根目錄， 然后到目錄中尋找相應(yīng)的日志文件（默認(rèn)會根據(jù)應(yīng)用程序池序號來區(qū)分目錄）。

比如：我找到了我需要的日志：

這個文件一大堆密密麻麻的字符，現(xiàn)在我該如何分析它呢？

有個叫 Log Parser 的工具就可以專門解析IIS日志，我們可以用它來查看日志中的信息。

比如我可以運(yùn)行下面的命令行（說明：為了不影響頁面寬度我將命令文本換行了）：

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

現(xiàn)在就可以以表格形式來閱讀IIS日志了：

說明：我不推薦用這種方法來分析IIS日志，原因有二點(diǎn)：

1. 慢：當(dāng)日志文件稍大一點(diǎn)的時候，用它來分析就比較浪費(fèi)時間了（尤其是需要多次統(tǒng)計時）。

2. 不方便：它支持的查詢語法不夠豐富，沒有像SQL Server針對數(shù)據(jù)表查詢那樣全面。

推薦的IIS日志分析方法

雖然Log Parser支持將解析的IIS日志以表格形式供人閱讀，但是有時候我們需要再做一些細(xì)致分析時，可能會按不同的方式進(jìn)行【多次】查詢， 對于這種需求，如果每次查詢都直接運(yùn)行Log Parser，你會浪費(fèi)很多時間。 幸運(yùn)的是，Log Parser支持將解析結(jié)果以多種格式導(dǎo)出（以下為幫助文檔截圖）：

在此，我建議選擇輸出格式為 SQL 。

注意：這里的SQL并不是指SQLSERVER，而是指所有提供ODBC訪問接口的數(shù)據(jù)庫。

我可以使用下面的命令將IIS日志導(dǎo)入到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

導(dǎo)入完成后，我們就可以用熟悉的SQLSERVER來做各種查詢和統(tǒng)計分析了，例如下面的查詢：

SELECT cip,csmethod,sport,csuristem,scstatus,scwin32status,scbytes,csbytes,timetaken FROM dbo.MyMVC_WebLog

如果如下：

注意：

1. IIS日志在將結(jié)果導(dǎo)出到SQLSERVER時，字段名中不符合標(biāo)識符規(guī)范的字符將會刪除。

例如：c-ip 會變成 cip， s-port 會變成 sport 。

2. IIS日志中記錄的時間是UTC時間，而且把日期和時間分開了，導(dǎo)出到SQLSERVER時，會生成二個字段：

date, time這二個字段看起來很不舒服，對吧？

我也很反感這個結(jié)果，下面來說說的二種解決方法：

1. 在SQLSERVER中增加一列，然后把UTC時間換成本地時區(qū)的時間，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. 直接在導(dǎo)出IIS日志時，把時間轉(zhuǎn)換過來，此時要修改命令：

"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這二列刪除了（你也可以在導(dǎo)出IIS日志時忽略它們，但要明確指出每個字段名）。

IIS日志中的UTC時間問題就說到這里，但愿每個人都懂了~~~~~~~~~~~

IIS日志中的異常記錄

IIS日志中記錄了每個請求的信息，包括正常的響應(yīng)請求和有異常的請求。

這里所說的【異常】與 .net framework 中的異常沒有關(guān)系。

對于一個ASP.NET程序來說，如果拋出一個未捕獲異常，會記錄到IIS日志中（500），但我所說的異常不僅限于此。

本文所說的異?？煞譃樗膫€部分：

1. （ASP.NET）程序拋出的未捕獲異常，導(dǎo)致服務(wù)器產(chǎn)生500的響應(yīng)輸出。

2. 404之類的請求資源不存在錯誤。

3. 大于500的服務(wù)器錯誤，例如：502，503

4. 系統(tǒng)錯誤或網(wǎng)絡(luò)傳輸錯誤。

前三類異?？梢杂孟旅娴牟樵儷@得：

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 ，它記錄了在處理請求過程中，發(fā)生的系統(tǒng)級別錯誤，例如網(wǎng)絡(luò)傳輸錯誤。

正常情況下，0 表示正常，出現(xiàn)非零值意味著出現(xiàn)了錯誤。我們可以這樣統(tǒng)計這類錯誤：

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

下表列出了比較常見的與網(wǎng)絡(luò)相關(guān)的錯誤及解釋：

所有狀態(tài)碼都可以通過下面的命令來獲取對應(yīng)的解釋：

D:\Temp>net helpmsg 64 指定的網(wǎng)絡(luò)名不再可用。

關(guān)于scwin32status與scStatus，我還想補(bǔ)充說明一下：它們沒有關(guān)聯(lián)。

比如請求這個地址：http://www.abc.com/test.aspx

有可能scStatus=200，但scwin32status=64，此時表示ASP.NET已成功處理請求，但是IIS在發(fā)送響應(yīng)結(jié)果時，客戶端的連接斷開了。

另一種情況是：scStatus=500，但scwin32status=0，此時表示，在處理請求過程中發(fā)生了未捕獲異常，但異常結(jié)果成功發(fā)送給客戶端。

再談 scwin32status=64

記得以前看到 scStatus=200，scwin32status=64 這種情況時很不理解，于是搜索了互聯(lián)網(wǎng)，各種答案都有，有的甚至說與網(wǎng)絡(luò)爬蟲有關(guān)。 為了驗(yàn)證各種答案，我做了一個試驗(yàn)。我寫一個ashx文件，用它來模擬長時間的網(wǎng)絡(luò)傳輸，代碼如下：

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這二個方法來模擬一個長時間的持續(xù)發(fā)送過程。

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

我把這個測試做了8次，只有2次是全部顯示完成了，其余6次我提前關(guān)閉了瀏覽器窗口。

然后，我們再來看IIS日志的內(nèi)容：

根據(jù)IIS日志并結(jié)合我自己的操作可以發(fā)現(xiàn)：

1. 當(dāng)我提前關(guān)閉瀏覽器窗口時，就會看到scStatus=200，scwin32status=64

2. 如果請求內(nèi)容全部顯示完成，我就會看到scStatus=200，scwin32status=0

從這個試驗(yàn)我們還可以發(fā)現(xiàn)：timeTaken 包含了網(wǎng)絡(luò)傳輸時間。

根據(jù)這個試驗(yàn)的結(jié)果，你是否想過一個問題：

如果你的網(wǎng)站的IIS日志中出現(xiàn)了大量的scStatus=200，scwin32status=64， 而且請求是由用戶的瀏覽器發(fā)起的。

這是什么原因造成的呢？

我的【猜想】是：用戶在訪問這個網(wǎng)站時已經(jīng)不愿意再等待了，他們把瀏覽器窗口關(guān)掉了。

換句話說：可以從scwin32status=64的統(tǒng)計結(jié)果看出網(wǎng)站的響應(yīng)速度是否能讓用戶滿意。

尋找性能問題

IIS日志中有一列叫：timeTaken，在IIS的界面中顯示了它的含義：所有時間。

這個所用時間的定義是：從服務(wù)端收到請求的***個字節(jié)開始起，直到把所有響應(yīng)內(nèi)容發(fā)送出去為止的時間。

微軟的網(wǎng)站有對這個字段做過說明：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情況的響應(yīng)情況，可以這樣查詢：

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 這二個字段也是值得我們關(guān)注的：

1. csbytes如果過大，我們就要分析一下到底是不是因?yàn)楸韱伟诉^多的無用數(shù)據(jù)，可否將表單拆分。

csbytes變大還有一種可能：Cookie太大，但它會表現(xiàn)為很多請求的csbytes都偏大，因此容易區(qū)分。

2. scbytes如果過大，我們就要檢查頁面是否沒有分頁，或者可以考慮用按需加載的方式來實(shí)現(xiàn)。

典型的情況是：當(dāng)大量使用ViewState時，這二個值都會變大。因此我們能通過IIS日志發(fā)現(xiàn)ViewState的濫用問題。

還有一種特殊情況是：上傳下載文件也會導(dǎo)致這二個數(shù)值變大，原因我就不解釋了。

scbytes,csbytes，不管是哪個數(shù)值很大，都會占用網(wǎng)絡(luò)傳輸時間，對于用戶來說，就需要更長的等待時間。

一下子說了三個字段，在尋找性能問題時，到底該參考哪個呢？

我認(rèn)為：應(yīng)該優(yōu)先關(guān)注timeTaken，因?yàn)樗臄?shù)值直接反映了用戶的等待時間（不包括前端渲染時間）。

如果timeTaken過大時，有必要檢查scbytes,csbytes是否也過大，

如果后二者也過大，那么優(yōu)化的方向就是減少數(shù)據(jù)傳輸量，否則表示是程序處理占用了大量的時間，應(yīng)該考慮優(yōu)化程序代碼。

尋找可改進(jìn)的目標(biāo)

除了可以從IIS日志中發(fā)現(xiàn)性能問題，還可以用它來尋找可改進(jìn)的目標(biāo)。

例如：

1. 有沒有404錯誤？

2. 是否存在大量的304請求？

3. 是否存在大量重復(fù)請求？

當(dāng)發(fā)現(xiàn)有404響應(yīng)時，我們應(yīng)該分析產(chǎn)生404的原因：

1. 是用戶輸入錯誤的URL地址嗎？

2. 還是開發(fā)人員引用不存在的資源文件？

如果是后者，就應(yīng)該盡快移除無效的引用，因?yàn)?04響應(yīng)也是一個頁面響應(yīng)，而且它們也會占用網(wǎng)絡(luò)傳輸時間， 尤其是這類請求不能緩存，它會一直出現(xiàn)，浪費(fèi)網(wǎng)絡(luò)資源。

如果你希望在開發(fā)階段就能輕易的發(fā)現(xiàn)404錯誤，可以參考我的博客：程序在發(fā)布前就應(yīng)該發(fā)現(xiàn)的一些錯誤

如果發(fā)現(xiàn)有大量的304請求也應(yīng)該仔細(xì)分析：

1. 是由于ASP.NET緩存響應(yīng)而產(chǎn)生的304請求嗎？

2. 還是請求靜態(tài)資源文件時產(chǎn)生的304請求？

如果是后者，則有可能與瀏覽器的設(shè)置有關(guān)，也有可能與IIS設(shè)置有關(guān)。

IIS有個【啟用內(nèi)容過期】功能，可用來在輸出響應(yīng)時設(shè)置緩存頭，減少請求數(shù)量。

此功能對靜態(tài)文件有用，ASP.NET處理的結(jié)果則不受影響。

具體設(shè)置方法可參考：不修改代碼就能優(yōu)化ASP.NET網(wǎng)站性能的一些方法

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

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

如果發(fā)現(xiàn)有大量的重復(fù)請求，也需要再仔細(xì)分析：

1. 請求的響應(yīng)內(nèi)容是否隨著不同的參數(shù)而各不相同？

2. 請求的URL是固定的，響應(yīng)內(nèi)容也是極少變化的。

如果是后者，則可以考慮使用頁面緩存功能。例如：ASP.NET的OutputCache

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

程序架構(gòu)對IIS日志分析過程的影響

前面我介紹了一些分析IIS日志的方法，這些方法的使用都離不開查詢。 絕大多數(shù)時候，我們需要在查詢中輸出URL信息（cs-uri-stem）并依據(jù)它們分組來統(tǒng)計， 因此，合理的設(shè)計URL會給后期的統(tǒng)計帶來方便， 也能得到更準(zhǔn)確的統(tǒng)計結(jié)果。 一個極端的反例是：采用WebForms默認(rèn)的開發(fā)方式，頁面加載以及每個按鈕的提交都是同一個URL，你會發(fā)現(xiàn)很難統(tǒng)計用戶的每個操作花了多少時間。

怎樣的URL設(shè)計才能滿足統(tǒng)計需要呢？

我認(rèn)為：每個用戶操作（頁面顯示或者提交）都應(yīng)該有一個URL與之對應(yīng)，且不同的URL能反映不同的操作。

另外還建議：不同的用戶操作能在URL中清楚的區(qū)分開，這樣能方便做更多的統(tǒng)計（例如：頁面加載，AJAX請求，報表顯示）。

雖然我們可以用timeTaken來做性能統(tǒng)計，然而，當(dāng)你在程序中大量使用frameset或者iframe時， 你將難以統(tǒng)計某個頁面（包含iframe的頁面）加載到底花了多長時間。 因?yàn)檎麄€頁面被分成了多個請求，它們在IIS日志中并不是連續(xù)的，你無法準(zhǔn)確地按用戶請求來統(tǒng)計。 例如：a1.aspx用iframe的方式嵌入了b1.aspx, b2.aspx, b3.aspx，當(dāng)你統(tǒng)計a1.aspx的加載時間時， 你得到的結(jié)果永遠(yuǎn)和用戶感受的情況不一樣，因?yàn)閍1.aspx的timeTaken并不包含b1.aspx, b2.aspx, b3.aspx這三個請求的timeTaken！

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

看完上述內(nèi)容，你們掌握網(wǎng)站運(yùn)維工具IIS日志的示例分析的方法了嗎？如果還想學(xué)到更多技能或想了解更多相關(guān)內(nèi)容，歡迎關(guān)注億速云行業(yè)資訊頻道，感謝各位的閱讀！