作者：格蠹老雷
來源：公眾號：格友
最近有些忙，幾個方面的事情需要做，不得不多任務模式工作，在幾臺電腦之間穿梭。但就在我焦急忙碌的時候，我的筆記本時不時會消極怠工，跟不上節奏。怠工的方式有多種，可能是打開程序很慢，可能是切換輸入法不靈活，有時Copy& Paste也會卡頓...... 觀察CPU使用率，沒有什么異常。根據經驗，估計是磁盤I/O方面的問題，但是一直沒有騰出時間深入分析。
收集數據
今天有些空閑，于是想清查一番，來一次嚴打。哪里下手呢？本著不冤枉一個好人，也不漏掉一個壞人的思想，先收集證據吧。調出WPA（Windows Performance Recorder），選擇“磁盤I/O、文件I/O、注冊表I/O和網絡I/O”，通過Windows系統的ETW機制從內核那里采集第一手資料。I/O專項整治開始。
一邊記錄，一邊觸發一些最近感覺緩慢的操作，持續了3分鐘后，點擊停止，保存事件，然后使用WPA打開分析。
誰家孩子玩硬盤
展開左側的File I/O子樹，選擇Activity by Process, Thread, Type分析，按訪問文件的字節數（Size）排名，立刻有驚人結果呈現。
各位看官睜大眼睛看上圖，排名第一的進程名叫wwbizsrv.exe。在采樣的幾分鐘時間里，它的文件I/O數據量是3個多G。穩居第一名，看起來相當于其后所有進程的總和。觀察文件屬性，文件說明里寫著“旺旺亮燈服務模塊”。亮燈服務？什么鬼？老雷的電腦不是選秀舞臺，也不是征婚現場啊？！
觀察版權描述，Alibaba Group，哇塞，看了這個名字，知道為啥如此囂張了。又是阿里家的軟件。幾年前曾領教過他家的支付寶客端，瘋狂觸發Page Fault，每秒鐘數千次。這次不再是支付寶客戶端了，而是旺旺。
WPA截圖中顯示的數據量是剛才采樣期間的，只有幾分鐘的長度，調出任務管理器，選擇I/O有關的計數器，想看一看開機以來的累計情況。
結果很快呈現在面前，按I/O讀取字節排名，旺旺又是穩居頭把交椅，總字節數大約1.6個TB。我的天啊，1.6TB什么概念，老雷電腦上的兩塊硬盤加起來的總容量也不到1.1TB，而整個維基百科的所有文本也只有大約1GB，所以1.6TB相當于把所有硬盤空間讀一遍，把維基百科讀1600多編。親啊，看你的圖標，一臉幼稚，懵懂無知的樣子，可你這是干什么啊？閑著空了，無聊了，就玩硬盤，是吧？
在系統服務列表里，也可以找到這個程序，描述里堂而皇之的寫著“為阿里旺旺客戶端提供基礎保障服務，一旦停止該服務，有可能影響您的阿里旺旺使用。”看來雖然圖標低調，但其實身份不一般，高居系統服務之位，已經進了系統的管理高層。但這個更要求你行為檢點，以身作則啊，不然，以低特權身份運行在瀏覽器里的插件們會增么想？各種廣告件又怎么想呢？“論起資源消耗，我還愧不如阿里家的旺旺呢！”
旺旺，你在讀什么？
從上面的WPA截圖來看，旺旺進程在大約3分鐘的時間里，做了8801次文件操作，其中3634次都是讀操作。于是，我很想知道，旺旺啊，你在讀什么？在我的電腦上找照片看呢么？
開個玩笑，還是要繼續以數據說話，在WPA里面選擇更多列，特別是文件路徑（File Path）。于是，旺旺剛才訪問的文件列表就在我們眼前了。
都訪問了哪些文件呢？一共3000多次，上面截圖只是其中一部分。讓老雷有點驚訝的是，訪問的文件類型大多都是DLL，DLL者，動態鏈接庫也。不是圖片，也不是文檔，DLL里面主要是程序，即資源和編譯后的代碼。
瀏覽這個列表，讓老雷更吃驚地的是，旺旺讀文件的方式很豪放，每一次讀操作，不是讀幾個字節，也不是讀幾十個字節，也不是讀幾百個字節，......而是一次讀大約1百萬字節。1百萬字節什么概念？老雷的《軟件調試》那本大厚書一共100多萬字。旺旺一次大約讀那么半本書（中文為雙字節編碼）。
另一個規律是，旺旺讀的差不多都是自己的文件，有一說一，真的是這樣。它沒有讀系統的，也沒有讀老雷的書稿。:-)
旺旺讀的最多的一個文件，名叫aef.dll，在資源管理器找到這個文件后，首先我讓我印象很深的是這個文件的塊頭，40多MB，其次是這個文件的說明和版權描述都為空白，不禁想起平凹前輩在《廢都》里的名句：“此處省略xx字”。
除了DLL文件外， 旺旺讀的較多的另一個文件名叫aef.pak，名字里也包含aef，一定和剛才aef.dll有關系，個頭大約是8MB，也不算小。
PAK是什么呢？應該是源于英文的package，即打包的意思，很多游戲程序常常把零零碎碎的各種小文件打包成PAK。旺旺或許也使用這個技術來打包零碎的文件。直接瀏覽文件內容，前面一小部分是二進制的，后面是來自Chromium的腳本。Chromium是著名的瀏覽器項目，旺旺的界面看起來就像是web風格的。
再往后面有很多JavaScript代碼。
看來旺旺讀的文件，主要都是代碼，有的是編譯過的DLL代碼，有的是腳本代碼。如此說來，旺旺像是在孤芳自賞，閑下來，便打開自己家的程序文件，閱讀里面的代碼。可能是在欣賞代碼里的優雅和智慧，也有可能是在使用達摩院里出來的最新最新的人工智能技術自動尋找瑕疵。也有可能.......
上調試器
做了20多年的軟件，看了旺旺所讀文件后，老雷已經大約猜出了旺旺的心思。可能是怕自己的代碼被人篡改，所以在檢查。
空猜無憑，還是上調試器找數據吧。喚出WinDBG，附加到旺旺服務，失敗，Access Denied，哦，忘了它是系統服務，重新以管理員身份運行WinDBG，賦予它高特權！再次附加，成功。
~*列出所有線程，一共8個，不算多。~*e .echo ***; ? @$tid;.ttime列出每個線程的執行時間，尋找用時間最久的線程。
0:008> ~*e .echo ***; ? @$tid;.ttime
***
Evaluate expression: 13676 = 0000356c
Created: Tue Jan 30 14:43:47.119 2018 (UTC + 8:00)
Kernel: 0 days 0:00:00.015
User: 0 days 0:00:00.062
***
Evaluate expression: 22780 = 000058fc
Created: Tue Jan 30 14:43:47.440 2018 (UTC + 8:00)
Kernel: 0 days 0:00:00.203
User: 0 days 0:00:00.046
***
Evaluate expression: 23472 = 00005bb0
Created: Tue Jan 30 14:43:47.782 2018 (UTC + 8:00)
Kernel: 0 days 0:14:18.125
User: 0 days 0:00:14.437
***
Evaluate expression: 19608 = 00004c98
Created: Tue Jan 30 14:43:47.784 2018 (UTC + 8:00)
Kernel: 0 days 0:00:00.078
User: 0 days 0:00:00.062
***
Evaluate expression: 21896 = 00005588
Created: Tue Jan 30 14:43:47.974 2018 (UTC + 8:00)
Kernel: 0 days 0:00:02.781
User: 0 days 0:00:01.281
***
Evaluate expression: 11992 = 00002ed8
Created: Thu Feb 8 10:37:43.331 2018 (UTC + 8:00)
Kernel: 0 days 0:00:00.000
User: 0 days 0:00:00.000
***
Evaluate expression: 15592 = 00003ce8
Created: Thu Feb 8 10:37:43.332 2018 (UTC + 8:00)
Kernel: 0 days 0:00:00.000
User: 0 days 0:00:00.000
***
Evaluate expression: 26820 = 000068c4
Created: Thu Feb 8 09:17:33.964 2018 (UTC + 8:00)
Kernel: 0 days 0:00:00.000
User: 0 days 0:00:00.000
***
Evaluate expression: 11336 = 00002c48
Created: Thu Feb 8 10:41:56.790 2018 (UTC + 8:00)
Kernel: 0 days 0:00:00.000
User: 0 days 0:00:00.000從列表可知，05bb0線程，花的CPU時間最長。切換到這個線程。執行k命令，觀察它的執行經過。
有人說，人生有三個基本問題，從哪里來，到哪里去，現在在干什么。軟件何嘗不是如此呢？但人生的三問題，比較難回答。而軟件的三個問題一條k命令的結果便是答案。
從上圖看，這個線程來自wwbizsrv模塊，也就是旺旺服務的主程序，因為沒有符號文件，我們只能看到幾個非常粗略的參照物。CPU在wwbizsrv模塊中執行了幾個函數后，開始調用系統的WaitForSingleObject函數，等待信號，進入內核。概括說來，這個線程來自旺旺服務的主模塊，目前在等待信號，處于休息狀態，它要往哪里去呢？
“讀硬盤啊！”
根據老雷推測，它現在是休息一會，休息好了，繼續玩硬盤。或者說，寫這段代碼的同行也知道，一直玩硬盤不行，要等一會，玩一下，等一會，玩一下。
等多久呢？看WaitForSingleObject函數的參數就知道了，第二個參數是001b7740 。十六進制的，不好理解，轉換一下：
0:002> ? 001b7740
Evaluate expression: 1800000 = 001b7740單位是毫秒，換算成分鐘是30，哦，看來是要等待30分鐘。如此看來，老雷剛才采樣3分鐘能捕捉到這個事件，也是幸運啊。亦或是天意。
輕敲鍵盤，對讀文件之要塞處埋個斷點，bp ntdll!NtReadFile，并給任務管理器做個截圖，留作后面比較，然后先做做其它事情。
疾風驟雨
半小時很快過去，斷點命中。果然是剛才的線程。
0:002> kcn
#
00 ntdll!NtReadFile
01 KERNELBASE!ReadFile
02 wwbizsrv!curl_formfree
03 wwbizsrv!curl_formfree
04 wwbizsrv!curl_formfree
05 wwbizsrv!curl_formfree
06 wwbizsrv!curl_formfree
07 wwbizsrv!OPENSSL_Applink
08 wwbizsrv!OPENSSL_Applink
09 KERNEL32!BaseThreadInitThunk
0a ntdll!__RtlUserThreadStart
0b ntdll!_RtlUserThreadStart再對打開文件的系統調用設置斷點，命中后觀察文件名，果然是在讀旺旺的DLL：
0:002> dU 01db22e8
01db22e8 "c:\program files (x86)\aliwangwa"
01db2328 "ng\9.12.02c\appmodel.dll"調整前面的兩個斷點，讓其自動打印和自動恢復執行，因為預計要讀很多個文件，對于讀很多次，如果每次手動觀察，那太累了。自動斷點設置好后，恢復旺旺執行，果然輸出不斷：
嘩嘩地輸出了幾十秒鐘后，終于安靜下來了，一波暴風雨過去了。上面截圖只是瘋狂輸出的一小小部分。其中靠下面的可以看到就是我們前面提到的aef.dll。
瘋狂過后，看瀏覽自動輸出，可以看到旺旺似乎是把旺旺客戶端的所有文件都讀了一遍，觀察旺旺目錄的大小，221MB。
再觀察任務管理器，I/O讀取字節指標已經由幾分鐘前的1724518253771，上升到1742116289711。
把瘋狂前后的兩個數字相減：
0:008> ?? 1742116289711-1724518253771
int64 0n17598035940
0:008> ? 0n17598035940
Evaluate expression: 17598035940 = 00000004`18ecb7e4差值大約是16.38GB。
0:008> ?? 17598035940/(1024*1024*1024.0)
double 16.389448139816523“讀你198遍，我不厭倦”
聰明的讀者看到這里可能有個疑惑，整個目錄的大小為221MB，那么讀一遍怎么在任務管理器里會上升16個GB呢？
坦率說，老雷起初也很困惑。后來仔細閱讀WinDBG的輸出信息，突然明白，天啊，原來旺旺不是只讀一遍，也不是讀兩遍，也不是10編，20遍，而是難以計數的遍數。
為了精確統計到底讀了多少遍，老雷特意把輸出結果復制到VC編輯器中，然后查找和替換aef.dll，發現有198遍。
直接把198*221，大約是42GB，那么旺旺可能每一遍不是讀整個目錄，而是目錄中的重要文件。具體清單可以查WinDBG的輸出，暫不追究。
那么旺旺為什么重復讀自己的文件呢？
老雷推測，旺旺讀自己文件的目的是為了檢查文件是否被篡改。應該是出于安全考慮吧，這是可以理解的。但是反復讀這么多次就沒有道理了。
為什么讀這么多次呢？可能在某一個函數里有個寫的不好的循環，也可能是團隊協作不好，各自寫代碼，各自讀文件，沒有復用讀到的文件內容。也可能是某個地方的代碼存在瑕疵。（如果此文的點贊次數超過2000，那么老雷便再花半天時間，找到198次的下落）
于是乎，有讀者可能會問，這樣的問題，測試不會發現么？從老雷幾次分析阿里軟件的經驗來推測，阿里的同行們似乎很少做性能測試。他們或許是覺得不需要，有那么多用戶測試呢。 :-)
對于這個問題，測試的難度也有一點，看起來是每半小時瘋狂讀一次，那么測試的如果不仔細，那么可能發現不了。
那么是誰做的這樣的設計呢？設計時就沒有考慮到性能的影響么？大家沒有review過這個設計么？團隊里的軟件架構師呢？高級程序員呢？項目經理呢？開發經理呢？
也有人想知道，這樣做的害處到底有多大呢？簡單回答，當這樣的瘋狂讀磁盤動作開始后，系統里的磁盤I/O隊列會變得很長。磁盤隊列長意味著讀磁盤要排長隊。
磁盤是系統的關鍵部件，很多操作都依賴磁盤。受影響的不僅僅是文件讀寫，還有系統里的Page Fault處理。因此，長的磁盤隊列會讓磁盤成為系統的瓶頸，影響整個系統的性能。頂層的表現就是系統緩慢，反應不靈活，甚至出現明顯的卡頓。
那么有人問，安全是必須的，不這樣做可以怎么做呢？首先不要重復那么多次，這個是初級程序員都懂的吧？其次是非要監視文件變化，怕黑客篡改，那么可以訂閱文件系統的文件修改事件啊。那樣不僅開銷小，而且可以及時收到通知。現在這個這樣，每半個小時，胡亂地讀一番，聰明的黑客可能在這個半小時的間隙里早把想做的事情做好了。安全重要，但是如何做安全，是要講究方法和策略的啊。
馬云先生說過，阿里早期發展時遇到的最大問題是“信任”問題，買家不相信賣家，不敢付錢，賣家不相信買家，不敢發貨.......最后的解決方法是通過數據建立信任，什么是數據，網頁上的每一句描述，旺旺聊天里的每一次對話，都是數據，都是憑證，都是信任的基礎。從這個角度上看，我們能更好理解地阿里為什么不復用現成的QQ，而是自己花力氣開發一個旺旺。從這個角度來看，旺旺對于阿里的成功乃至于整個中國互聯網的蓬勃發展都是有巨大貢獻的，可謂功勛卓著。
但是也有名人說過，信任很脆弱，是很容易破碎的。今天，廣大的用戶因為信任阿里，所以大家都幾乎不猶豫的安裝了旺旺。但是看到旺旺如此瘋狂地訪問硬盤，無謂地消耗系統資源，老雷真的很生氣，其它用戶可能也很生氣。惹惱了的用戶可能把這個淘氣的孩子趕出系統。剛剛，老雷已經把排名在旺旺后的DELL程序和Akamai程序刪除掉了，并把旺旺服務設置為禁用狀態，只允許其在規定時間運行，并希望阿里的同行能早日修正這個問題。
本文由 Seebug Paper 發布，如需轉載請注明來源。本文地址：http://www.bjnorthway.com/531/
暫無評論