2020-12-25

分析一个驱动程序导致程序无响应的案例

最近有客户投诉我们的程序经常无响应，几乎无法使用。我查看了问题现场，发现有以下表现：

1. 无响应时程序的CPU使用率基本保持为0%。
2. 如果一直放着不干预，一分钟左右程序是能恢复正常的。
3. 从转储文件看，程序是在调用ReadFile读取文件内容时出现无响应的，部分的堆栈如下所示：

ntdll!KiFastSystemCallRet
ntdll!NtReadFile+0xc
KERNELBASE!ReadFile+0xaa
kernel32!ReadFileImplementation+0xf0
MyApp!winRead+0xc6
MyApp!sqlite3OsRead+0x2c
MyApp!sqlite3WalReadFrame+0x45
MyApp!readDbPage+0x94
MyApp!getPageNormal+0x1a4
MyApp!sqlite3PagerGet+0x13
MyApp!getAndInitPage+0x72
MyApp!moveToChild+0x7f
MyApp!sqlite3BtreeMovetoUnpacked+0x3c5
MyApp!sqlite3VdbeExec+0x2b31
MyApp!sqlite3Step+0xee
MyApp!sqlite3_step+0x98

根据这些现象，我猜测可能是某个实现不好的驱动程序拦截了ReadFile这个API导致的。为了进一步排查，需要更详尽的信息，于是我在客户的电脑上使用Windows Performance Recorder录制性能数据，从无响应开始，一直录制到恢复正常，然后使用Windows Performance Analyzer对这个性能数据进行分析。下面是分析过程。

在这里主要用到的是Windows Performance Analyzer的“CPU Usage (Precise)”图表，这个图表的数据与线程的状态切换息息相关。简单来说，在线程的生命周期中，会在以下几种状态之间切换：

• 等待，线程要执行的条件未被满足，正在等待这些条件。例如，线程在等待一个互斥锁被释放。
• 就绪，线程要执行的所有条件均已满足，随时可以调度给CPU执行。例如，一个线程释放了互斥锁，另外一个正在等待锁的线程会进入就绪状态。
• 执行，线程正在被CPU执行。

Windows Performance Recorder记录了系统中所有线程每一次状态切换的信息，包括就绪之前等待的时长、哪个线程让另一个线程就绪、导致线程进入等待状态的堆栈等等，这些信息均通过CPU Usage (Precise)图表来呈现。

回到本文要分析的问题，“程序在一分钟左右能恢复正常”是一个很关键的信息，它表明了导致程序无响应的一个可能原因：主线程在等待某个条件，经过一分钟左右该条件得到满足，主线程得以继续执行，于是程序恢复正常。为了证实这个猜想，需要从CPU Usage (Precise)图表中找到证据。

在打开了CPU Usage (Precise)图表之后，先对这个表格的列做一些调整，如下所示：

这里把表格黄色分割线左侧的列，依次设置成了“New Process” - “New Thread Id” - “New Thread Stack”，这几个带有“New”前缀的列表示切换到执行状态的线程的相关信息，例如New Process表示线程所在进程的名字，New Thread Id即该线程的ID，New Thread Stack表示切换到执行状态之后，线程开始执行时代码位置的堆栈，这通常也是线程进入等待状态时的堆栈。经过这样设置之后，表格的数据会依次按照进程-线程-堆栈来聚合，方便筛选和查看。

然后是表格蓝色分割线右侧的列设置成了“Waits”的最大值，顾名思义，Waits这个数据的含义是线程在切换到就绪状态之前等待的时长。注意这不是切换到执行状态之前的等待时长。从就绪状态切换到执行状态之间也有一段时间，这段时间不会计算在内，而且通常这段时间都很短，相比在等待状态的时长，可以忽略不计。

接下来，将表格按照Waits列倒序排列，并且根据进程名字和主线程ID进行筛选，即可找到等待时长最大的线程状态切换数据，从这个数据的堆栈，能看出来一些端倪，如下所示：

从图中可以看到，主线程在这一次切换到执行状态之前等待了大约77秒，符合程序无响应的感官时长，而且图中展示的堆栈与转储文件中的堆栈是一致的，所以基本可以确定这里就是问题产生的根源。相比用户态的转储文件，Windows Performance Analyzer的一个优势是可以看到内核态的堆栈，可以看到调用ReadFile之后发生的事情。这里有一个可疑的驱动程序cwNep.sys，它没有符号信息，并且网上搜索的结果表明，它显然是一个第三方的驱动程序。这个驱动程序调用了FltSendMessage，该函数使主线程进入了等待状态。

查阅FltSendMessage的文档，可以知道这个API是内核态的驱动程序向用户态的应用程序发消息时使用的，并且它是一个阻塞式的同步调用，如果应用程序没有调用FilterGetMessage来接收消息，驱动程序就会一直等待，直到消息被接收或者超时。

至此，问题的原因已经很清楚了，cwNep.sys驱动程序拦截了ReadFile调用，并且向用户态的应用程序发消息，而该应用程序没有及时接收这个消息，导致调用线程进入长时间的等待状态。

既然已经找到了肇事的驱动程序，那么可以继续找一下是哪个应用程序没有及时接收消息。基于程序可以从无响应中恢复的现象，可以确定要找的应用程序最终是成功调用了FilterGetMessage。从文档可知，FilterGetMessage既可以同步调用也可以异步调用，暂且假设它是被同步调用的，那么调用这个函数的线程，在接收到驱动程序的消息之后，必然会从等待状态切换到就绪状态，继而切换到执行状态，并且它开始执行的堆栈也是在FilterGetMessage内部。所以，可以在New Thread Stack这一列中查找FilterGetMessage关键字，如下所示：

在这个案例中，运气不错，很快找到了唯一一个调用了FilterGetMessage的线程，如下所示：

由此确定这个没有及时接收消息的应用程序是wepsvc.exe。

Windows, 性能, 调试, Windows Performance Toolkit