對(duì)于一個(gè)需要長(zhǎng)期維護(hù)的網(wǎng)站來(lái)說(shuō)，如何讓網(wǎng)站長(zhǎng)久穩(wěn)定運(yùn)行是件很有意義的事情。有些在開(kāi)發(fā)階段沒(méi)有暴露的問(wèn)題很有可能就在運(yùn)維階段出現(xiàn)了，這也是很正常的。還有些時(shí)候，我們希望不斷地優(yōu)化網(wǎng)站，讓網(wǎng)站更快速的響應(yīng)用戶請(qǐng)求，這些事情都發(fā)生在開(kāi)發(fā)之后的運(yùn)維階段。
與開(kāi)發(fā)階段不同的，運(yùn)維階段不可能讓你去調(diào)試程序，發(fā)現(xiàn)各類(lèi)問(wèn)題，我們只能通過(guò)各種系統(tǒng)日志來(lái)分析網(wǎng)站的運(yùn)行狀況，對(duì)于部署在IIS上的網(wǎng)站來(lái)說(shuō)，IIS日志提供了最有價(jià)值的信息，我們可以通過(guò)它來(lái)分析網(wǎng)站的響應(yīng)情況，來(lái)判斷網(wǎng)站是否有性能問(wèn)題，或者存在哪些需要改進(jìn)的地方。
IIS日志包含了哪些信息
我前面說(shuō)到【IIS日志提供了最有價(jià)值的信息】，這些信息有哪些呢？看看這個(gè)截圖吧：
這里面記錄了：
1. 請(qǐng)求發(fā)生在什么時(shí)刻，
2. 哪個(gè)客戶端IP訪問(wèn)了服務(wù)端IP的哪個(gè)端口，
3. 客戶端工具是什么類(lèi)型，什么版本，
4. 請(qǐng)求的URL以及查詢字符串參數(shù)是什么，
5. 請(qǐng)求的方式是GET還是POST，
6. 請(qǐng)求的處理結(jié)果是什么樣的：HTTP狀態(tài)碼，以及操作系統(tǒng)底層的狀態(tài)碼，
7. 請(qǐng)求過(guò)程中，客戶端上傳了多少數(shù)據(jù)，服務(wù)端發(fā)送了多少數(shù)據(jù)，
8. 請(qǐng)求總共占用服務(wù)器多長(zhǎng)時(shí)間、等等。
這些信息在分析時(shí)有什么用途，我后面再說(shuō)。先對(duì)它有個(gè)印象就可以了。
IIS日志的配置
默認(rèn)情況下，IIS會(huì)產(chǎn)生日志文件，不過(guò)，還是有些參數(shù)值得我們關(guān)注。IIS的設(shè)置界面如下（本文以 IIS 8 的界面為例）。
在IIS管理器中，選擇某個(gè)網(wǎng)站，雙擊【日志】圖標(biāo)，請(qǐng)參考下圖：
此時(shí)（主要部分）界面如下：
在截圖中，日志的創(chuàng)建方式是每天產(chǎn)生一個(gè)新文件，按日期來(lái)生成文件名（這是默認(rèn)值）。
說(shuō)明：IIS使用UTC時(shí)間，所以我勾選了最下面的復(fù)選框，告訴IIS用本地時(shí)間來(lái)生成文件名。
點(diǎn)擊【選擇字段】按鈕，將出現(xiàn)以下對(duì)話框：
注意：【發(fā)送的字段數(shù)】和【接收的字節(jié)數(shù)】默認(rèn)是沒(méi)有選擇的。建議勾選它們。
至于其它字段，你可以根據(jù)需要來(lái)決定是否要勾選它們。
如何分析IIS日志
如果你按照我前面介紹的方法設(shè)置了IIS日志參數(shù)，那么IIS在處理請(qǐng)求后（的一段時(shí)間之后），會(huì)生成IIS日志。
我們可以在【日志界面】的右邊區(qū)域【操作】中點(diǎn)擊【查看日志文件】快速定位到IIS日志的根目錄，然后到目錄中尋找相應(yīng)的日志文件（默認(rèn)會(huì)根據(jù)應(yīng)用程序池序號(hào)來(lái)區(qū)分目錄）。
比如：我找到了我需要的日志：
這個(gè)文件一大堆密密麻麻的字符，現(xiàn)在我該如何分析它呢？
有個(gè)叫 Log Parser 的工具就可以專(zhuān)門(mén)解析IIS日志，我們可以用它來(lái)查看日志中的信息。
比如我可以運(yùn)行下面的命令行（說(shuō)明：為了不影響頁(yè)面寬度我將命令文本換行了）：
"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)在就可以以表格形式來(lái)閱讀IIS日志了：
說(shuō)明：我不推薦用這種方法來(lái)分析IIS日志，原因有二點(diǎn)：
1. 慢：當(dāng)日志文件稍大一點(diǎn)的時(shí)候，用它來(lái)分析就比較浪費(fèi)時(shí)間了（尤其是需要多次統(tǒng)計(jì)時(shí)）。
2. 不方便：它支持的查詢語(yǔ)法不夠豐富，沒(méi)有像SQL Server針對(duì)數(shù)據(jù)表查詢那樣全面。
推薦的IIS日志分析方法
雖然Log Parser支持將解析的IIS日志以表格形式供人閱讀，但是有時(shí)候我們需要再做一些細(xì)致分析時(shí)，可能會(huì)按不同的方式進(jìn)行【多次】查詢，對(duì)于這種需求，如果每次查詢都直接運(yùn)行Log Parser，你會(huì)浪費(fèi)很多時(shí)間。幸運(yùn)的是，Log Parser支持將解析結(jié)果以多種格式導(dǎo)出（以下為幫助文檔截圖）：
在此，我建議選擇輸出格式為 SQL 。
注意：這里的SQL并不是指SQLSERVER，而是指所有提供ODBC訪問(wèn)接口的數(shù)據(jù)庫(kù)。
我可以使用下面的命令將IIS日志導(dǎo)入到SQLSERVER中（說(shuō)明：為了不影響頁(yè)面寬度我將命令文本換行了）：
"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來(lái)做各種查詢和統(tǒng)計(jì)分析了，例如下面的查詢：
SELECT cip,csmethod,sport,csuristem,scstatus,scwin32status,scbytes,csbytes,timetaken
FROM dbo.MyMVC_WebLog
如果如下：
注意：
1. IIS日志在將結(jié)果導(dǎo)出到SQLSERVER時(shí)，字段名中不符合標(biāo)識(shí)符規(guī)范的字符將會(huì)刪除。
例如：c-ip 會(huì)變成 cip， s-port 會(huì)變成 sport 。
2. IIS日志中記錄的時(shí)間是UTC時(shí)間，而且把日期和時(shí)間分開(kāi)了，導(dǎo)出到SQLSERVER時(shí)，會(huì)生成二個(gè)字段：
date, time這二個(gè)字段看起來(lái)很不舒服，對(duì)吧？
我也很反感這個(gè)結(jié)果，下面來(lái)說(shuō)說(shuō)的二種解決方法：
1. 在SQLSERVER中增加一列，然后把UTC時(shí)間換成本地時(shí)區(qū)的時(shí)間，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日志時(shí)，把時(shí)間轉(zhuǎn)換過(guò)來(lái)，此時(shí)要修改命令：
"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日志時(shí)忽略它們，但要明確指出每個(gè)字段名）。
IIS日志中的UTC時(shí)間問(wèn)題就說(shuō)到這里，但愿每個(gè)人都懂了~~~~~~~~~~~
IIS日志中的異常記錄
IIS日志中記錄了每個(gè)請(qǐng)求的信息，包括正常的響應(yīng)請(qǐng)求和有異常的請(qǐng)求。
這里所說(shuō)的【異常】與 .net framework 中的異常沒(méi)有關(guān)系。
對(duì)于一個(gè)ASP.NET程序來(lái)說(shuō)，如果拋出一個(gè)未捕獲異常，會(huì)記錄到IIS日志中（500），但我所說(shuō)的異常不僅限于此。
本文所說(shuō)的異常可分為四個(gè)部分：
1. （ASP.NET）程序拋出的未捕獲異常，導(dǎo)致服務(wù)器產(chǎn)生500的響應(yīng)輸出。
2. 404之類(lèi)的請(qǐng)求資源不存在錯(cuò)誤。
3. 大于500的服務(wù)器錯(cuò)誤，例如：502，503
4. 系統(tǒng)錯(cuò)誤或網(wǎng)絡(luò)傳輸錯(cuò)誤。
前三類(lèi)異常可以用下面的查詢獲得：
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 ，它記錄了在處理請(qǐng)求過(guò)程中，發(fā)生的系統(tǒng)級(jí)別錯(cuò)誤，例如網(wǎng)絡(luò)傳輸錯(cuò)誤。
正常情況下，0 表示正常，出現(xiàn)非零值意味著出現(xiàn)了錯(cuò)誤。我們可以這樣統(tǒng)計(jì)這類(lèi)錯(cuò)誤
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
下表列出了比較常見(jiàn)的與網(wǎng)絡(luò)相關(guān)的錯(cuò)誤及解釋?zhuān)?/p>
| scWin32Status |
含義 |
| 64 |
客戶端連接已關(guān)閉（或者斷開(kāi)） |
| 121 |
傳輸超時(shí) |
| 1236 |
本地網(wǎng)絡(luò)中斷 |
所有狀態(tài)碼都可以通過(guò)下面的命令來(lái)獲取對(duì)應(yīng)的解釋?zhuān)?/p>
D:\Temp>net helpmsg 64指定的網(wǎng)絡(luò)名不再可用。
關(guān)于scwin32status與scStatus，我還想補(bǔ)充說(shuō)明一下：它們沒(méi)有關(guān)聯(lián)。
比如請(qǐng)求這個(gè)地址：http://www.abc.com/test.aspx
有可能scStatus=200，但scwin32status=64，此時(shí)表示ASP.NET已成功處理請(qǐng)求，但是IIS在發(fā)送響應(yīng)結(jié)果時(shí)，客戶端的連接斷開(kāi)了。
另一種情況是：scStatus=500，但scwin32status=0，此時(shí)表示，在處理請(qǐng)求過(guò)程中發(fā)生了未捕獲異常，但異常結(jié)果成功發(fā)送給客戶端。
再談 scwin32status=64
記得以前看到 scStatus=200，scwin32status=64 這種情況時(shí)很不理解，于是搜索了互聯(lián)網(wǎng)，各種答案都有，有的甚至說(shuō)與網(wǎng)絡(luò)爬蟲(chóng)有關(guān)。為了驗(yàn)證各種答案，我做了一個(gè)試驗(yàn)。我寫(xiě)一個(gè)ashx文件，用它來(lái)模擬長(zhǎng)時(shí)間的網(wǎng)絡(luò)傳輸，代碼如下：
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");
}
段代碼很簡(jiǎn)單，我不想做過(guò)多的解釋?zhuān)幌胝f(shuō)一句：我用Thread.Sleep與Response.Flush這二個(gè)方法來(lái)模擬一個(gè)長(zhǎng)時(shí)間的持續(xù)發(fā)送過(guò)程。
我們可以在瀏覽器中看到這樣的輸出（顯示還沒(méi)有完全結(jié)束時(shí)我截圖了）
我把這個(gè)測(cè)試做了8次，只有2次是全部顯示完成了，其余6次我提前關(guān)閉了瀏覽器窗口。
然后，我們?cè)賮?lái)看IIS日志的內(nèi)容：
根據(jù)IIS日志并結(jié)合我自己的操作可以發(fā)現(xiàn)：
1. 當(dāng)我提前關(guān)閉瀏覽器窗口時(shí)，就會(huì)看到scStatus=200，scwin32status=64
2. 如果請(qǐng)求內(nèi)容全部顯示完成，我就會(huì)看到scStatus=200，scwin32status=0
從這個(gè)試驗(yàn)我們還可以發(fā)現(xiàn)：timeTaken 包含了網(wǎng)絡(luò)傳輸時(shí)間。
根據(jù)這個(gè)試驗(yàn)的結(jié)果，你是否想過(guò)一個(gè)問(wèn)題：
如果你的網(wǎng)站的IIS日志中出現(xiàn)了大量的scStatus=200，scwin32status=64，而且請(qǐng)求是由用戶的瀏覽器發(fā)起的。
這是什么原因造成的呢？
我的【猜想】是：用戶在訪問(wèn)這個(gè)網(wǎng)站時(shí)已經(jīng)不愿意再等待了，他們把瀏覽器窗口關(guān)掉了。
換句話說(shuō)：可以從scwin32status=64的統(tǒng)計(jì)結(jié)果看出網(wǎng)站的響應(yīng)速度是否能讓用戶滿意。
尋找性能問(wèn)題
IIS日志中有一列叫：timeTaken，在IIS的界面中顯示了它的含義：所有時(shí)間。
這個(gè)所用時(shí)間的定義是：從服務(wù)端收到請(qǐng)求的第一個(gè)字節(jié)開(kāi)始起，直到把所有響應(yīng)內(nèi)容發(fā)送出去為止的時(shí)間。
微軟的網(wǎng)站有對(duì)這個(gè)字段做過(guò)說(shuō)明：http://support.microsoft.com/kb/944884
知道了timeTaken的定義后，我們就可以利用它來(lái)分析一些請(qǐng)求的處理時(shí)間，即性能分析。
例如，我想查看最慢的20個(gè)頁(yè)面的加載情況，可以這樣查詢：
select top 20 csuristem,scstatus,scwin32status,scbytes,csbytes,timetakenfrom dbo.MyMVC_WebLog with(nolock)where csUriStem like '/Pages/%'order by timeTaken desc
再或者我想再看看最慢的20個(gè)AJAX情況的響應(yīng)情況，可以這樣查詢：
select top 20 csuristem,scstatus,scwin32status,scbytes,csbytes,timetaken
from dbo.MyMVC_WebLog with(nolock)
where csUriStem like '/Pages/%'
order by timeTaken desc
再或者我想再看看最慢的20個(gè)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
總之，尋找性能問(wèn)題的方法就是：在查詢選擇timeTaken字段，并且用它做降序排序。
注意：scbytes,csbytes 這二個(gè)字段也是值得我們關(guān)注的：
1. csbytes如果過(guò)大，我們就要分析一下到底是不是因?yàn)楸韱伟诉^(guò)多的無(wú)用數(shù)據(jù)，可否將表單拆分。
csbytes變大還有一種可能：Cookie太大，但它會(huì)表現(xiàn)為很多請(qǐng)求的csbytes都偏大，因此容易區(qū)分。
2. scbytes如果過(guò)大，我們就要檢查頁(yè)面是否沒(méi)有分頁(yè)，或者可以考慮用按需加載的方式來(lái)實(shí)現(xiàn)。
典型的情況是：當(dāng)大量使用ViewState時(shí)，這二個(gè)值都會(huì)變大。因此我們能通過(guò)IIS日志發(fā)現(xiàn)ViewState的濫用問(wèn)題。
還有一種特殊情況是：上傳下載文件也會(huì)導(dǎo)致這二個(gè)數(shù)值變大，原因我就不解釋了。
scbytes,csbytes，不管是哪個(gè)數(shù)值很大，都會(huì)占用網(wǎng)絡(luò)傳輸時(shí)間，對(duì)于用戶來(lái)說(shuō)，就需要更長(zhǎng)的等待時(shí)間。
一下子說(shuō)了三個(gè)字段，在尋找性能問(wèn)題時(shí)，到底該參考哪個(gè)呢？
我認(rèn)為：應(yīng)該優(yōu)先關(guān)注timeTaken，因?yàn)樗臄?shù)值直接反映了用戶的等待時(shí)間（不包括前端渲染時(shí)間）。
如果timeTaken過(guò)大時(shí)，有必要檢查scbytes,csbytes是否也過(guò)大，
如果后二者也過(guò)大，那么優(yōu)化的方向就是減少數(shù)據(jù)傳輸量，否則表示是程序處理占用了大量的時(shí)間，應(yīng)該考慮優(yōu)化程序代碼。
尋找可改進(jìn)的目標(biāo)
除了可以從IIS日志中發(fā)現(xiàn)性能問(wèn)題，還可以用它來(lái)尋找可改進(jìn)的目標(biāo)。
例如：
1. 有沒(méi)有404錯(cuò)誤？
2. 是否存在大量的304請(qǐng)求？
3. 是否存在大量重復(fù)請(qǐng)求？
當(dāng)發(fā)現(xiàn)有404響應(yīng)時(shí)，我們應(yīng)該分析產(chǎn)生404的原因：
1. 是用戶輸入錯(cuò)誤的URL地址嗎？
2. 還是開(kāi)發(fā)人員引用不存在的資源文件？
如果是后者，就應(yīng)該盡快移除無(wú)效的引用，因?yàn)?04響應(yīng)也是一個(gè)頁(yè)面響應(yīng)，而且它們也會(huì)占用網(wǎng)絡(luò)傳輸時(shí)間，尤其是這類(lèi)請(qǐng)求不能緩存，它會(huì)一直出現(xiàn)，浪費(fèi)網(wǎng)絡(luò)資源。
