一次掛死（hang)的處理過程及經驗

作者: 黑山小妖來源: 博客園發布時間: 2009-06-21 20:25 閱讀: 4181 次推薦: 0 原文鏈接 [收藏]

前言：

CPU占用率低，內存還有許多空余，但網站無法響應，這就是網站掛死，通常也叫做hang。這種情況對于我這樣既是CEO,又是CTO，還兼職掃地洗碗的個人站長來說根本就是家常便飯。以下是一次處理hang的經驗及總結，前后用了一個月，不僅涉及程序排查，數據庫優化，還有硬件升級的苦惱。其中辛酸苦辣只有經歷過的站長才能體會，希望此文能對各位有所幫助！

首先介紹一下網站基本情況，是一個在線小說閱讀網站，每天有一定頁面訪問量，在優化開始前由兩臺服務器運行，均為Dell PowerEdge 2950，配置為一臺Intel xeon E5410 2.33G*2 ,4GB ECC內存，另一臺Intel xeon E5405 2.0G*2 ,2GB ECC內存。
網站程序采用asp.net 2.0,操作系統為 windows 2003 server 企業版，數據庫為Ms sqlserver 2005。數據庫放在配置較低的那臺機器上，網站小說圖片和章節內容用EMC Replistor同步。

問題描述：

大概在五月中旬，網站速度開始變慢，根據讀者的描述每當中午以后每間隔一段時間，瀏覽器處于連接的狀態，但是一直沒有收到服務器的響應，打開下一個頁面往往需要一兩分鐘。這種情況持續大概5分鐘后打開速度恢復正常，然后隔相同時間又出現。
登陸服務器觀察CPU波動在10%-30%之間，w3wp.exe內存占用500M左右，應該不是內存溢出或者泄露。觀察任務管理中“聯網”一項，發現服務器流量有如下變化：

顯然在hang期間服務器沒有對外發送任何數據。

初步嘗試：

是什么造成服務器假死呢？根據讀者的描述：“中午以后”可以知道hang出現在訪問人數較大的時期，“間隔相同時間出現”提示我們有可能是服務器某些資源被耗盡造成死鎖，然后服務器回收，接著再次耗盡。
有了以上判斷，我們就有路可循了,估計問題無非出在IIS6，ASP.NET 2.0 ，MSSQL SERVER 2005這三個服務的配置上：

            1. 檢查IIS設置,主要檢查應用程序池里的設置,看看核心請求隊列有沒有限制. 可以參考《Windows Server 2003 性能調整指南》
            2. 檢查ASP.NET的http管道設置，具體是machine.config下的節點，可以參考《ASP.net 2.0:我還有多少秘密你不知道？(1)》
            3 MS SQLSERVER暫時沒有想到有什么需要修改的，保持默認設置。

經過檢查發現IIS設置沒有問題，machine.config配置文件下processModel為autoConfig="true"，于是把requestQueueLimit修改為15000，另外還修改了其他一些配置。上傳后發現問題依舊，這下郁悶了，難道還有什么會造成服務器資源消耗后回收？

答案是顯然的，.NET環境下確實有這么一個東西： GC！
會不會是由于GC在壓縮和回收垃圾造成網站無法響應？如何監視GC運行的情況呢？

答案也是顯然的：性能監視器（(轉)Windows 性能監視器工具-perfmon）
性能監視器下的.Net CLR Memory Object有很多關于GC的計數器，能讓我們了解GC的詳細工作情況。但是經過觀察發現在hang期間和hang之前都沒有GC運行的明顯變化，我的天啊，也不是GC的問題，那會是什么呢？

相信很多和我一樣的菜鳥小站長到這個地步已經垂頭喪氣了，難道我們現在應該到論壇或者博客園發帖然后禱告哪個高手好心幫幫忙花點小力氣解決一下？我們是否還有一些遺忘的東西？或者說我們是不是忽略了問題的本質？這里的問題顯然是由于IIS無法響應請求，確切的來說是ASP.NET無法正常的響應請求（為什么是ASP.NET而不是IIS？猜的！），那有沒有辦法知道ASP.NET在hang期間正在進行什么工作呢？有的!這就是.net愛好者人手一把的神器級工具:windbg

神器windbg:

       Windbg是微軟發布的一款用于調試和debug的免費工具，可以在http://www.microsoft.com/whdc/DevTools/Debugging/default.mspx下載。
      我們主要利用windbg抓取hang期間的dump用于分析，其他windbg的功能請參考園子里的資料。
      在服務器上下載并安裝好windbg后，進入命令行，轉到C:\Program Files\Debugging Tools for Windows (x86)\目錄下，
      輸入 adplus –hang –pn w3wp.exe – quiet,但是不要急著按回車，等到出現hang情況再按，這樣我們就在目錄下得到一個dump文件，其大小與w3wp.exe進程大小相同。（adplus及如何自動抓取參考園子里資料）。
      把dump文件下載到本地后，運行自己機器上的windbg打開dump文件（windbg初始配置請參考資料），輸入：
      1 .load sos
      此命令加載.net 調試器，具體設置請參考資料
      2 !threads
      查看當前運行的進程，得到結果如下，省略了一部分：
0:000> !threads
ThreadCount: 245
UnstartedThread: 0
BackgroundThread: 245
PendingThread: 0
DeadThread: 0
Hosted Runtime: no
                                      PreEmptive   GC Alloc           Lock
       ID OSID ThreadOBJ    State     GC       Context       Domain   Count APT Exception
11    1 9e4 000e96a0   1808220 Enabled 00000000:00000000 0010f680     1 MTA (Threadpool Worker)
23    2 f48 000bd750      b220 Enabled 00000000:00000000 000eac88     0 MTA (Finalizer)
25    3 1324 00104370   180b220 Enabled 00000000:00000000 0010f680     1 MTA (Threadpool Worker)
26    4 4f8 00106980   180b220 Enabled 00000000:00000000 0010f680     1 MTA (Threadpool Worker)
27    5 9ec 0010bd38    80a220 Enabled 00000000:00000000 000eac88     0 MTA (Threadpool Completion Port)
。。。。。。。

      我們可以看到當前一共有245個進程正在運行，根據熊力大師的《windows用戶態高效排錯》P164頁上描述（剛好例子也是博客園），超過30個線程估計程序中有blocking發生，那我們245個線程就是由blokiiiiiiiiing發生了，仔細檢查一下，沒有線程處于GC狀態，說明blocking不是因為GC，證實了我上面的推斷。
      接著輸入：
       ~* e!clrstack 看看這些線程都在執行什么，結果發現幾乎所有的進程都在執行同一個過程，如下（閱讀請從下往上看，因為是stack）：

24aeeb60 7c9585ec [NDirectMethodFrameStandalone: 24aeeb60] Microsoft.Win32.Win32Native.CloseHandle(IntPtr)
24aeeb70 7927984d Microsoft.Win32.SafeHandles.SafeFileHandle.ReleaseHandle()
24aeed90 79e71b4c [GCFrame: 24aeed90]
24aeef88 79e71b4c [GCFrame: 24aeef88]
24aeeff4 79e71b4c [HelperMethodFrame_1OBJ: 24aeeff4] System.Runtime.InteropServices.SafeHandle.InternalDispose()
24aef04c 792e5e06 System.Runtime.InteropServices.SafeHandle.Dispose(Boolean)
24aef054 792e5ddd System.Runtime.InteropServices.SafeHandle.Dispose()
24aef05c 792eb580 System.IO.FileStream.Dispose(Boolean)
24aef090 792dfc82 System.IO.Stream.Close()
24aef09c 79271d90 System.IO.StreamReader.Dispose(Boolean)
24aef0c8 792d88ad System.IO.TextReader.Dispose()
24aef0d0 1d879f07 XXXXXX.BLL.Chapter.ChapterContent(Int32, Int32)
24aef110 1d879e14 XXXXX.BLL.Chapter.GetChapterContent(Int32, Int32)
24aef120 1d874a4e XXXXX.ReadContent.Page_Load(System.Object, System.EventArgs)
24aef164 66f2a7ff System.Web.Util.CalliHelper.EventArgFunctionCaller(IntPtr, System.Object, System.Object, System.EventArgs)
24aef174 660b2344 System.Web.Util.CalliEventHandlerDelegateProxy.Callback(System.Object, System.EventArgs)
24aef188 660ab864 System.Web.UI.Control.OnLoad(System.EventArgs)
24aef19c 660ab8a3 System.Web.UI.Control.LoadRecursive()
24aef1b4 660a7954 System.Web.UI.Page.ProcessRequestMain(Boolean, Boolean)
24aef30c 660a7584 System.Web.UI.Page.ProcessRequest(Boolean, Boolean)
24aef344 660a74b1 System.Web.UI.Page.ProcessRequest()
24aef37c 660a7446 System.Web.UI.Page.ProcessRequestWithNoAssert(System.Web.HttpContext)
24aef388 660a7422 System.Web.UI.Page.ProcessRequest(System.Web.HttpContext)
24aef39c 26bff7d5 ASP.readcontent_aspx.ProcessRequest(System.Web.HttpContext)
24aef3a0 660ad8f6 System.Web.HttpApplication+CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
24aef3d4 6608132c System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef)
24aef414 6608c3a3 System.Web.HttpApplication+ApplicationStepManager.ResumeSteps(System.Exception)
24aef464 660808ac System.Web.HttpApplication.System.Web.IHttpAsyncHandler.BeginProcessRequest(System.Web.HttpContext, System.AsyncCallback, System.Object)
24aef480 66083e1c System.Web.HttpRuntime.ProcessRequestInternal(System.Web.HttpWorkerRequest)
24aef4b4 66083ac3 System.Web.HttpRuntime.ProcessRequestNoDemand(System.Web.HttpWorkerRequest)
24aef4c4 66082c5c System.Web.Hosting.ISAPIRuntime.ProcessRequest(IntPtr, Int32)
24aef6d8 79f68c4e [ContextTransitionFrame: 24aef6d8]
24aef70c 79f68c4e [GCFrame: 24aef70c]
24aef868 79f68c4e [ComMethodFrame: 24aef868]
OS Thread Id: 0x17d4 (109)

這下問題很明顯了，是由于XXXXXX.BLL.Chapter.ChapterContent(Int32, Int32)引發磁盤IO操作造成鎖定，ChapterContent是讀取小說章節內容的一個函數，小說內容保存在txt文件中，每一個章節對應一個txt文件，在顯示章節內容時首先讀取txt的文件然后打印到網頁當中。具體代碼如下：

        private static string ChapterContent(int bookId, int chapterId)
        {
            string filepath = siteRoot + string.Format(chapterPath, bookId.ToString(), chapterId.ToString());

            if (File.Exists(filepath))
            {
               return File.ReadAllText(filepath, Encoding.UTF8);
            }

string bookPath = siteRoot + "/book/" + bookId.ToString();

            if (!Directory.Exists(bookPath))
            {
                Directory.CreateDirectory(bookPath);
            }
            return "此文章內容丟失，請復制網址通知管理員";
        }

代碼看起來沒有問題，查看源碼知道File.ReadAllText內部用了using讀取文件，應該是及時釋放了的，那么估計問題出在大量IO同時進行，導致非托管代碼出現了blocking（SafeHandle是.net2.0增加的保證程序可靠性的東東，熊力大師的書上有描述），那么問題是，如何得到一個支持大量IO操作，具有線程安全的文件系統呢？等等，這話聽起來好熟悉，這不就是數據庫嗎？？！
OK，這下我們的信心又從火星飛回來了，趕快動手寫程序把txt文件導入數據庫中，經過3天時間的終于把200多萬個TXT章節共計17GB導入到ms sqlserver2005中（夜間人少的時候進行）。本以為這下搞定了，卻不知道是另一場噩夢的開始！
站長之路何其艱辛！

數據庫噩夢：

好不容易把txt章節導入到數據庫里，運行一天下來速度的確有那么一點提升，可是讀者的抱怨依然沒有減少，每當高峰時期速度還是一如既往的慢。這次又是怎么回事呢？老辦法運起神器windbg，按照上一節的操作后發現一共有101個線程，大部分線程都在執行：
2036ec90 7c9585ec [InlinedCallFrame: 2036ec90] .SNIReadSync(SNI_Conn*, SNI_Packet**, Int32)
2036ec8c 65226f0a SNINativeMethodWrapper.SNIReadSync(System.Runtime.InteropServices.SafeHandle, IntPtr ByRef, Int32)
2036ecfc 65226c14 System.Data.SqlClient.TdsParserStateObject.ReadSni(System.Data.Common.DbAsyncResult, System.Data.SqlClient.TdsParserStateObject)
2036ed34 65611041 System.Data.SqlClient.TdsParserStateObject.ReadNetworkPacket()
2036ed44 65228680 System.Data.SqlClient.TdsParserStateObject.ReadBuffer()
2036ed50 65228609 System.Data.SqlClient.TdsParserStateObject.ReadByte()
2036ed5c 65609b88 System.Data.SqlClient.TdsParser.Run(System.Data.SqlClient.RunBehavior, System.Data.SqlClient.SqlCommand, System.Data.SqlClient.SqlDataReader, System.Data.SqlClient.BulkCopySimpleResultSet, System.Data.SqlClient.TdsParserStateObject)
2036edc8 65220f12 System.Data.SqlClient.SqlDataReader.ConsumeMetaData()
2036eddc 65220a34 System.Data.SqlClient.SqlDataReader.get_MetaData()
2036ee08 6521f396 System.Data.SqlClient.SqlCommand.FinishExecuteReader(System.Data.SqlClient.SqlDataReader, System.Data.SqlClient.RunBehavior, System.String)
2036ee40 6521eff5 System.Data.SqlClient.SqlCommand.RunExecuteReaderTds(System.Data.CommandBehavior, System.Data.SqlClient.RunBehavior, Boolean, Boolean)
2036ee8c 6521edf3 System.Data.SqlClient.SqlCommand.RunExecuteReader(System.Data.CommandBehavior, System.Data.SqlClient.RunBehavior, Boolean, System.String, System.Data.Common.DbAsyncResult)
2036eed0 6521ed31 System.Data.SqlClient.SqlCommand.RunExecuteReader(System.Data.CommandBehavior, System.Data.SqlClient.RunBehavior, Boolean, System.String)
2036eeec 6521ec3e System.Data.SqlClient.SqlCommand.ExecuteReader(System.Data.CommandBehavior, System.String)
2036ef2c 6521ea5d System.Data.SqlClient.SqlCommand.ExecuteDbDataReader(System.Data.CommandBehavior)
2036ef30 6521fcab System.Data.Common.DbCommand.System.Data.IDbCommand.ExecuteReader(System.Data.CommandBehavior)
2036ef38 652300e3 System.Data.Common.DbDataAdapter.FillInternal(System.Data.DataSet, System.Data.DataTable[], Int32, Int32, System.String, System.Data.IDbCommand, System.Data.CommandBehavior)
2036ef90 65230010 System.Data.Common.DbDataAdapter.Fill(System.Data.DataSet, Int32, Int32, System.String, System.Data.IDbCommand, System.Data.CommandBehavior)
2036efd4 6522fe9f System.Data.Common.DbDataAdapter.Fill(System.Data.DataSet)
2036f004 1e5b9e73 xxxx.SQLServerDAL.SqlHelper.ExecuteDataset(System.Data.SqlClient.SqlConnection, System.Data.CommandType, System.String, System.Data.SqlClient.SqlParameter[])
2036f020 1e5b9dbf XXXX.SQLServerDAL.SqlHelper.ExecuteDataset(System.String, System.Data.SqlClient.SqlParameter[])
2036f050 1e5b9d48 XXXX.SQLServerDAL.Book.GetBookContent(Int32)
2036f064 1e5b879f XXXX.BLL.Book.GetBookContent(Int32)
2036f098 1e5b3315 XXXX.ReadBook.Page_Load(System.Object, System.EventArgs)
2036f0f8 66f2a7ff System.Web.Util.CalliHelper.EventArgFunctionCaller(IntPtr, System.Object, System.Object, System.EventArgs)
2036f108 660b2344 System.Web.Util.CalliEventHandlerDelegateProxy.Callback(System.Object, System.EventArgs)
2036f11c 660ab864 System.Web.UI.Control.OnLoad(System.EventArgs)
2036f130 660ab8a3 System.Web.UI.Control.LoadRecursive()
2036f148 660a7954 System.Web.UI.Page.ProcessRequestMain(Boolean, Boolean)
2036f2a0 660a7584 System.Web.UI.Page.ProcessRequest(Boolean, Boolean)
2036f2d8 660a74b1 System.Web.UI.Page.ProcessRequest()
2036f310 660a7446 System.Web.UI.Page.ProcessRequestWithNoAssert(System.Web.HttpContext)
2036f31c 660a7422 System.Web.UI.Page.ProcessRequest(System.Web.HttpContext)
2036f330 1b66aed5 ASP.readbook_aspx.ProcessRequest(System.Web.HttpContext)
2036f334 660ad8f6 System.Web.HttpApplication+CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
2036f368 6608132c System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef)
2036f3a8 6608c3a3 System.Web.HttpApplication+ApplicationStepManager.ResumeSteps(System.Exception)
2036f3f8 660808ac System.Web.HttpApplication.System.Web.IHttpAsyncHandler.BeginProcessRequest(System.Web.HttpContext, System.AsyncCallback, System.Object)
2036f414 66083e1c System.Web.HttpRuntime.ProcessRequestInternal(System.Web.HttpWorkerRequest)
2036f448 66686c53 System.Web.RequestQueue.WorkItemCallback(System.Object)
2036f460 792c9dff System.Threading._ThreadPoolWaitCallback.WaitCallback_Context(System.Object)
2036f468 792f5611 System.Threading.ExecutionContext.runTryCode(System.Object)
2036f88c 79e71b4c [HelperMethodFrame_PROTECTOBJ: 2036f88c] System.Runtime.CompilerServices.RuntimeHelpers.ExecuteCodeWithGuaranteedCleanup(TryCode, CleanupCode, System.Object)
2036f8f4 792f5507 System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
2036f910 792e0175 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
2036f928 792ca363 System.Threading._ThreadPoolWaitCallback.PerformWaitCallbackInternal(System.Threading._ThreadPoolWaitCallback)
2036f93c 792ca1f9 System.Threading._ThreadPoolWaitCallback.PerformWaitCallback(System.Object)
2036facc 79e71b4c [GCFrame: 2036facc]
2036fc18 79e71b4c [ContextTransitionFrame: 2036fc18]

毫無疑問，是由于某些函數（如GetBookContent）操作數據庫造成SQL Blocking,打開GetBookContent執行的SQL語句，如下（是一存儲過程）：

SELECT [ID], [Name] FROM dbo.Book_ChapterCategory WHERE Book_ID = @bookid
SELECT dbo.Book_Chapter.Chapter_ID,dbo.Book_Chapter.ChapterName,dbo.Book_Chapter.Category_ID,dbo.Book_Chapter.IsVipChapter
FROM dbo.Book_Chapter WHERE dbo.Book_Chapter.Book_ID = @bookid ORDER BY dbo.Book_Chapter.Chapter_ID

兩條很簡單的查詢語句，沒有什么問題，操作數據庫過程中也用了using確保連接關閉。那會是什么問題呢？再仔細訊問讀者如何定義“服務器卡死了”的描述，發現問題和以前一樣，也是無法響應一段時候后恢復正常再無法響應，那又是用盡某些資源然后回收？可是我們已經導入數據庫了呀！數據庫，數據庫，噢！對了，ADO.NET處理數據庫連接時候用到連接池技術，會不會是已經達到了默認上限（默認是100）了呢？運起另外一件神器性能監視器查看（參照上節文章），果然已經達到上限，這下好辦，我們修改連接字符串為以下（請參考SqlConnection..::.ConnectionString 屬性）：

server=XXX;user id=XXX;password=XXX;database=XXX;Max Pool Size =500;Connection Lifetime=300;

這下連接池上限改成500了,滿懷信心的傳上去，結果無比郁悶，單獨web那臺服務器運行比較正常，但是同時運行web和database那臺服務器幾乎是無法對外響應！OK，一臺服務器不應該承擔過多的職責，幸好家里還有一臺淘汰下來的DELL PE 1850機器，趕緊讓老媽跑到電信局去申請托管（我在上海讀書，服務器放在家里的城市），被告知需要領導審批3天后才能上架，極其難受的度過3天，那臺老服務器終于用上。趕緊把數據庫轉移到老服務器上，心想這下搞定了吧！

現實和理想總是有一定差距，這就是人生。新上架的服務器雖然解決了“一段時間無法響應，過一會好了，然后再無法響應“的問題，但速度依然很慢，表現為性能監視器 Asp.net Application里Request in Applicatong Queue一直有許多請求未處理，但是不會像以前一樣完全無法響應。還有新的問題出現，在涉及大數據量操作的時候會提示發生死鎖！OMG，程序也沒改變，訪問量也沒大變化，一直以來都沒問題，怎么會發生死鎖呢！那叫一個郁悶呀！

由于之前沒有發生過，那估計是新托管的服務器處理速度不夠導致的死鎖，經過搜索后得知打開MS SQL SERVER 2005 的READ_COMMITTED_SNAPSHOT選項（參看SQL Server 2005使用基于行版本控制的隔離級別初探）能夠提供基于行版本控制的隔離級別，這意味著讀取操作不會阻止更新操作。但是打開這個選項要求暫停數據庫所有事務，所以我選擇了另外一個方法，在查詢語句添加 with(nolock)達到同樣的效果.
但是事與愿違，速度依然沒有得到改善，看來只能升級數據庫服務器的硬件，于是一個電話打到DELL訂購一臺PE 2950,花了1萬7大洋，銷售代表小姐甜甜地告訴我需要7個工作日內服務器才能寄到家里，這一天是2009-6-4號（值得紀念嗎？）。
服務器還沒到，那就不妨再檢查看看還有什么可以優化的地方，既然是由于數據庫服務器運行速度慢導致的阻塞，那能不能優化SQL操作來提高速度呢？首先找出具體引起死鎖的語句，采用《檢測死鎖》一文中提供的儲存過程發現這個存儲過程有問題：

SELECT Book_Book.*, Book_Category.Description AS CategoryName
FROM Book_Book WITH(NOLOCK) LEFT JOIN
Book_Category WITH(NOLOCK) ON Book_Book.Category_ID = Book_Category.Category_ID
WHERE Book_Book.Book_ID = @Book_ID
UPDATE Book_Book WITH (ROWLOCK) SET VisitedCount=VisitedCount+1,MonthHits=MonthHits+1,DayHits=DayHits+1,WeekVisitedCount=WeekVisitedCount+1 WHERE [Book_ID] = @Book_ID

該過程檢索小說信息后，順便增加點擊數，列Book_ID建立了聚集索引，注意到已經在select語句中加上with(nolock)，為什么這個語句會引起死鎖呢？關鍵在于后面一個update，大量的并發操作和較低的硬件配置使得服務器在執行此update時速度緩慢，而執行update會加上排它鎖，進而造成死鎖（但是我用了行級鎖，為什么還會這樣呢？），把update刪除后大部分死鎖也沒有了，但是一個網站不能不統計點擊數，咨詢DUDU，他建議把點擊數分出一個單獨的表。但是這樣做會是一個大的工程，所以只好在不繁忙的時段才統計點擊數，等待新服務器的到來。
在不改變表的情況下，接著對其他存儲過程進行優化，借助 SQL SERVER2005中數據庫引擎優化顧問建立索引，十分傻瓜式，但是這個東西也不能全信，有些讀者反映一個頁面打開特別慢，顯示執行超時，檢查后發現是如下SQL語句(簡化過)

SELECT
一堆列名
FROM
Book_Book LEFT JOIN Book_Chapter
ON
Book_Book.LastChapterID = Book_Chapter.Chapter_ID
LEFT JOIN dbo.Book_ChapterCategory
ON
Book_Chapter.Category_ID = Book_ChapterCategory.ID
WHERE
Book_Book.Moderator_ID =@UserID
ORDER BY
Book_Chapter.Addtime desc

      此存儲過程設計三個表，在我機器上的數據量分別是
Book_Book                     15145行
Book_Chapter                 1006603行
Book_ChapterCategory        45928行

在SQL Server Management Studio中執行該過程，并選擇窗口欄上“包括執行計劃”，得到結果集 11455行，執行計劃如圖：

把鼠標移動到各個方框上會顯示詳細的執行信息，重點關注開銷比較大的，移動到那個開銷為53%的上面，顯示：

       其中對象里顯示的_dta_index_Book_Chapter_5_308964227__K1_K6_K5_2是數據庫引擎優化顧問建立的非聚集索引，在Book_Chapter上建立[Chapter_ID] ASC, [Category_ID] ASC, [Addtime] ASC。
我們注意到物理類型為索引掃描，實際行數是1006603，等等，這不就是整個Book_Chapter表的所有行數嗎？為什么要掃描整個表？按照我的思路應該首先從Book_Book里根據Moderator_ID的索引找出符合Moderator_ID =@UserID的11455行記錄，然后根據Book_Book.LastChapterID = Book_Chapter.Chapter_ID從Book_Chapter找出11455行記錄，再從Book_ChapterCategory找出11455條記錄然后合并，整個過程因為有索引不需要進行整表掃描才對。
      于是刪除Book_Chapter上的_dta_index_Book_Chapter_5_308964227__K1_K6_K5_2索引，并建立[chapter_ID ASC],[Book_ID] ASC的索引。再次執行，執行計劃如圖：

其中開銷66%的詳細信息為：

這下物理運算變成索引查找了，實際行數也變成了期望的11438行（有些書還沒有章節，所以比11455少），我們再對SQL語句優化一下，改成（紅色字體是改變過的地方）：

SELECT
一堆列名
FROM
Book_Book LEFT JOIN （Book_Chapter LEFT JOIN dbo.Book_ChapterCategory
ON
Book_Chapter.Category_ID = Book_ChapterCategory.ID
）
ON
Book_Book.LastChapterID = Book_Chapter.Chapter_ID
WHERE
Book_Book.Moderator_ID =@UserID
ORDER BY
Book_Chapter.Addtime desc

執行結果如下：

      這次查詢簡單多了，至少能在一個圖片完全顯示整個查詢結構。而且發現我們在上一步優化中建立的索引IX_Book_Chapter沒用用上，而是用了Book_Chapter本來的主鍵聚集索引查找。
      經過測試優化后這條語句執行速度比優化前快了45%
      對所有操作頻繁的存儲過程進行優化后，速度沒有明顯的提高！依然很慢，看來真的是需要等待新的服務器了。

消費者的無奈：

服務器是在6月4號購買的，6月7號媽媽打電話告訴我服務器到了，速度還挺快。大家首先來看看服務器的報價單，這幾張圖片是我截圖下來的，實際的報價單被分成好幾塊，每一塊都有很多重復的信息（用來干擾視線的？）：

      各位有看出報價單里面有什么不對嗎？反正當時我就看了CPU,內存和硬盤，檢查沒錯后確認了，6月8日幫我裝機器的yang13老師告訴我寄過來的電源是48V DC，他在學校里不能用，然后我打電話到電信局IDC，技術工程師告訴我他們主要用220V交流電，讓我換了220V的再托管。我回頭翻出報價單一看，在最后的倒數第二欄果然有一個小小的-48VDC,當時沒在意，想著打個電話給DELL讓他們換一換就行了。
第二天一大早我就打電話給DELL的銷售代表，這位小姐說她不懂技術，又讓我打給技術支持，技術說這個的確錯了，而且只能更換，讓我和銷售調換，然后我再次打電話給銷售，她說這個要CC（customer care客戶關懷部）給我處理，她已經提交上去了。這時我就郁悶，我好好的買一個服務器怎么就需要被關懷了呢？不過算了，還是等等吧。
      一直等到星期五下午4點多（6月12號），一個自稱是客戶關懷部的小姐打電話給我說出了什么問題，電源壞了嗎？我當時氣憤的不行，這已經過了3天了，她們還搞不清楚電源是壞了還是錯了，有這樣的服務態度嗎？然后我打電話給銷售，沒人接，打電話給技術，沒人接。周末DELL公司不上班，星期一我再打給銷售，發現換人了，原來賣給我的銷售因某某某原因休假，接替她的人對這件事情什么都不知道，難道我要從頭來一次？氣憤！然后打電話給技術，技術又撥通了客戶關懷部進行3方通話，這次客戶關懷部說他們是按照訂單上寫的生產，沒有出錯，不給退換，我當時就郁悶，對她說你是在中國境內賣服務器為什么默認配48V 直流電源而不是中國標準220V交流電源？然后這位客戶關懷部的小姐就不說按照訂單生產，反而一再問我是不是提了什么特殊要求，我當時根本就沒提什么要求，完全是按照正常流程，居然把責任推給我，這實在讓人失望。然后我說你們不是有為了保證服務質量有電話錄音的嗎？找出來看看不就知道了，現在那名銷售也知道去哪里了，你們想說什么就是什么了吧？
      電話那頭沉默了幾秒，然后說：我們是按照訂單生產，不能換。
      我馬上掛掉電話。到網上買了兩個2950的220V電源，6月18號終于把新服務器裝上，一切問題都解決了！

后記：

      這次hang排查過程前后花了一個月的時間，真可謂一波三折。
      總結出來的經驗：
      1. 用性能監視器查看系統運行情況。
      2. 用windbg抓取dump后用~*e!clrstack看看hang期間在執行什么
      3. 對癥下藥
      通過這3步一般就能解決問題。但僅僅解決了技術上的問題，現實中有許多困難往往來自非技術上的，這對于像我這樣單槍匹馬的個人站長+技術愛好者來說是經常有的情況，但是一個好的站長必須不怕困難，堅持自己的信念才能走到最后。