而且還是陣發性的,有某個用戶投訴慢的時候,你訪問卻很快,本地又復現不出來?今天你訪問了博客園真是太幸運了,也許這裡就有你想要的一個答案——假如你的站點動態處理了圖片或者其他原本不會動態處理的非網頁資源的話。沒想到吧,這是Session惹的禍!
我們公司某個站點訪問量一直很大,幾年前就已經發現客戶經常投訴說很慢,而這個問題我們一直都在排查和解決。從線路問題,到數據庫連接洩露,到數據庫死鎖、索引,以及程序的優化問題,我們都查找過,並且解決過。然而,這個問題總還是存在。比如說,在IIS日志中,就會經常看到time-taken大於10秒鐘的訪問。而最近我們的KPI要求解決這個問題,不得已,再次踏上這趟艱難的排查之旅。
之所以說艱難,是因為這個現象在本地幾乎無法復現,一個是這個現象是陣發性的,第二個是本地訪問量或者數據量不夠大。我們也嘗試過在本地加載線上服務器的數據庫,然後拿服務器的IIS的Log文件重播,結果確實是偶爾發現IIS日志中的time-taken也會比較長,但是本地服務器性能不如線上服務器的,比如說IO就差很遠,於是總說不清楚到底是什麼問題。而線上服務器也不方便用做Dump的形式查找:第一是因為線上一做Dump,站點就會在幾分鐘內失去響應,這樣我們客服的電話就會被打爆;另一個原因還是陣發性的問題,我們不可能一直盯著性能看,然後在發生問題的瞬間做Dump。再說了,看性能也看不出來,因為那些響應時間很長的訪問,其前後附近的響應都特別的快。不可避免的,我們只能夠在代碼裡面塞入一些調試和日志的代碼,以期望能夠得到一些有用的信息。
最開始的時候,我們認為最可能的原因是數據庫阻塞,比如正好某一個訪問鎖住某個數據庫對象(比如一張表或者某幾行),如果這個時候訪問特定的頁面,可能就會比較慢。於是在數據庫層塞入了一堆代碼,這些代碼會在數據庫連接數量多,或者某個數據庫連接時間特別長的時候,將所有數據庫連接的當前訪問語句、連接持續總時間,以及這些連接當前的堆棧情況都輸出到文件中。與此同時,我們還打開Sql profiler對這個數據庫進行監視,將持續時間超過1秒鐘的都記錄下來。然而跑了一天之後,卻發現什麼都沒有被記錄下來,但IIS日志中仍然在這段時間內出現許多10秒以上的訪問。這個時候,我們就意識到,可能方向錯了。
接著,我們就開始塞另外一段代碼:一個IHttpModule。這個模塊就只是截獲每一個頁面訪問的完整生命周期中的所有事件,比如BeginRequest、PreAuthenticateRequest等。同時在BeginRequest開始的時候設置一個定時器,每隔一秒鐘就會出發一個事件,來記錄本次訪問過程中,本模塊收集到的所有線程中當前的堆棧情況。最後,在EndRequest的時候,如果訪問時間超過5秒,就將之前截獲的所有信息輸出到文件中。這一下子問題就變得非常的清晰了,比如說,下面這種輸出(片斷)就是非常典型的一個情況:
#Steps:
#Fields: date time threadId stepName
#---------------------------------------------------
2009-07-09 16:48:01.752 0024 BeginRequest
2009-07-09 16:48:01.752 0024 AuthenticateRequest
2009-07-09 16:48:01.752 0024 PostAuthenticateRequest
2009-07-09 16:48:01.752 0024 AuthorizeRequest
2009-07-09 16:48:01.752 0024 PostAuthorizeRequest
2009-07-09 16:48:01.752 0024 ResolveRequestCache
2009-07-09 16:48:01.752 0024 PostResolveRequestCache
2009-07-09 16:48:01.752 0024 PostMapRequestHandler
2009-07-09 16:48:06.284 0007 AcquireRequestState
2009-07-09 16:48:06.284 0007 PostAcquireRequestState
2009-07-09 16:48:06.284 0007 PreRequestHandlerExecute
2009-07-09 16:48:06.284 0007 EndRequest
#---------------------------------------------------
#End of steps.
也就是說,在PostMapRequestHandler之後,AcquireRequestState之前,有一大段的等待時間。而這個報告後面的堆棧情況,則顯得很奇怪:線程7從第一次截快照的時候開始,一直到結束都是空白的!甚至在其他的一些報告中甚至會發現這個線程已經被分派處理其他頁面的工作了(堆棧中的調用很明顯指出是另一個aspx頁面的代碼)。結果一Google“PostMapRequestHandler”和“AcquireRequestState”這兩個關鍵字,就找到了國外另一個有類似遭遇的受害者:
http://forums.iis.net/t/1147300.aspx 這個樓主是一個aspx頁面裡面有好幾個iframe,並且每一個iframe裡面都是訪問同一個Web應用下的Aspx頁面。現象就是iframe內的頁面會一個個蹦出來,尤其是這些頁面都比較慢的時候。和我這裡截獲到的情況一樣,也是PostMapRequestHandler事件到AcquireRequestState之間有很長的空白時間。順籐摸瓜,又找到了這麼一個帖子:
http://www.microsoft.com/communities/newsgroups/en-us/default.aspx?dg=microsoft.public.dotnet.framework.aspnet&mid=7f56033f-caac-47c2-bd9c-95512aa14b47 原來,在AcquireRequestState之前,需要等待上一個同SessionId的頁面處理完畢之後,才會繼續處理當前頁面。其根本原因是:同一個SessionId下面的Session對象不應該被同時寫入,否則就會全亂套了,原理和多線程競爭是一樣的。因此在設計上,同一個SessionId的頁面(或者IHttpHandler)就會順序執行。
好了,到這裡真相又一次大白了!(指不定還有別的問題,還會有下一次大白的時候)在我們的系統中,由於特殊的原因,對圖片的輸出我們會通過Asp.Net來處理,比如說加上一些合適的緩存標記,甚至會動態生成圖片輸出(令人驚訝的是,這個動態輸出的總時間消耗甚至不到100毫秒,所以不要說動態生成是一種不好的實施方式)。但是,由於沒有經過特殊處理,Asp.Net底層認為這些訪問時需要對Session進行寫操作的,於是就在AcquireRequestState之前掛起,等待上一次同SessionId訪問結束。可想而知,圖片多了就會導致排隊,甚至排很長的隊。如果在排隊結束之前訪問下一個頁面,正好系統又沒有丟掉之前的隊列,則這次訪問就會變得比較漫長了。那麼怎麼做呢? 在一次順籐摸瓜,找到了確切的說法:
http://msdn.microsoft.com/en-us/library/ms178581.aspx 注意下面的這段話:
Concurrent Requests and Session State
Access to ASP.NET session state is exclusive per session, which means that if two different users make concurrent requests, access to each separate session is granted concurrently. However, if two concurrent requests are made for the same session (by using the same SessionID value), the first request gets exclusive access to the session information. The second request executes only after the first request is finished. (The second session can also get access if the exclusive lock on the information is freed because the first request exceeds the lock time-out.) If theEnableSessionState value in the @ Page directive is set to ReadOnly, a request for the read-only session information does not result in an exclusive lock on the session data. However, read-only requests for session data might still have to wait for a lock set by a read-write request for session data to clear.
也就是說,對於頁面,我們可以簡單的在Aspx上的<% @Page %>內設置EnableSessionState=”false”,或者EnableSessionState=”ReadOnly”,就可以減輕這種問題的症狀。前一種設置將會禁止對Session的訪問,而後一種設置則只能允許只讀訪問(你不能夠對Session進行寫操作)。正好,我們剛才提到的IHttpHandler中,對圖片進行處理的部分,是不需要對Session進行寫操作的,但是卻需要讀取Session(根據狀態不同,而需要獲取一些特殊信息),因此可以采取上述的措施來解決問題。
上述參考文獻中,並沒有說明如何對不是Page的IHttpHandler如何設置,這裡我特別說明一下。對於自定義的一個實現了IHttpHandler接口的類,只要同時實現IReadOnlySessionState,即可達到EnableSessionState="ReadOnly"的效果。同時,如果沒有實現IRequiresSessionState,則等價於EnableSessionState=”false”的效果。
注意:本文所說的,不是說你在代碼裡面有沒有用到Session,Asp.Net不會掃描你的代碼看看有沒有訪問Session,或者在你第一次訪問Session的時候才會加鎖。Asp.Net是在AcquireRequestState事件之前就首先申請這個鎖——只要你的頁面沒有設置EnableSessionState=”false”或EnableSessionState=”ReadOnly”,或者你的IHttpHandler實現了IRequiresSessionState卻沒有實現IReadOnlySessionState接口就會這樣。回復中有很多同學說“只要我不用Session不就行了嗎?”或者“我從來不用Session”,這麼想完全是錯誤的,只能說你沒有理解這背後的機制,甚至可能連Asp.net生命周期都不太清楚。Asp.Net之所以在你的頁面代碼開始執行之前就鎖定,是要保證整個環境的完整性,避免部分執行的情況。當然,也正如上面的一些引用中所提到的,你可以自己寫一個SessionProvider而不做任何的鎖工作,但這樣做肯定有不確定性的風險,到時候只能你自己承擔,並且更難復現和調試。
後記:
可能有不少人都知道Session是什麼,也有很多人知道Asp.net的生命周期都包含哪些,比如一搜索"PostMapRequestHandler AcquireRequestState",就會出來很多中文的頁面介紹HttpApplication類都有哪些事件,以及生命周期等等。而說到Session會造成特殊情況下站點性能問題的,似乎中文界我這還真是第一篇。當然了,這個問題可能比較偏,因為一般大家都只會處理Aspx頁面而不會處理圖片,甚至用Aspx頁面來動態輸出圖片的機會都比較少,英文的似乎也只有文中提到的唯一一個同志提出來了。
不過,有一個很常見的場景會受這個問題的影響,那就是“驗證碼”。如果驗證碼生成速度很慢,同時客戶端浏覽器選擇長連接而服務器也接受長連接,則可能會影響在輸出驗證碼完畢之前訪問下一個頁面的速度。反過來,我們也經常可以體驗到,驗證碼出來的速度總是特別慢,總是“蹦”出來的,尤其是當前頁面特別復雜的時候,似乎頁面沒有加載完就總不會出現驗證碼。估計我說的問題就是原因之一。
不過驗證碼的問題還不是特別好解決,因為為了避免信息洩露的問題,驗證碼的答案通常是存在在Session裡面的,而通常的設計也是一訪問驗證碼圖片,就會將驗證碼答案寫到Session裡面。所以,很不幸,文中提到的那個解決辦法是行不通的,至少不是能夠直接行得通的。這個問題有沒有救藥?有,當然有了。怎麼救?哈,那就有勞你自己開動腦筋了,我這裡算是點到即止了。