谁家娃娃玩硬盘

2018-02-08 格蠹老雷 格友 格友

    最近有些忙,几个方面的事情需要做,不得不多任务模式工作,在几台电脑之间穿梭。但就在我焦急忙碌的时候,我的笔记本时不时会消极怠工,跟不上节奏。怠工的方式有多种,可能是打开程序很慢,可能是切换输入法不灵活,有时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程序删除掉了,并把旺旺服务设置为禁用状态,只允许其在规定时间运行,并希望阿里的同行能早日修正这个问题。