Re: 求解，printf一去不复返的问题。

C/C++本地代码调试

求解，printf一去不复返的问题。

CutlerMao 2015-09-20, 13:15 下午
问题描述：

我的服务端程序是windows平台的程序，运行于Windows Server 2008 R2 SP1 x64系统上。执行一段时间后（多久不确定，有时候几天，有时候一个月也说不定），会出现printf无法输出问题。

此时，卡住的printf调用堆栈如下：

57 Id: 2024.249c Suspend: 0 Teb: 7ef00000 Unfrozen

ChildEBP RetAddr Args to Child

0fdce050 762e1314 00000007 0fdce0e8 00000042 kernel32!WriteConsoleInternal+0x15

0fdce06c 762e12f5 00000007 0fdce0e8 00000042 kernel32!WriteConsoleA+0x18

0fdce088 71547819 00000007 0fdce0e8 00000042 kernel32!WriteFileImplementation+0x6f

0fdcfba0 7154711f 00000001 00533e98 00000040 msvcr110!_write_nolock+0x501

0fdcfbe4 7153dffc 00000001 00533e98 00000040 msvcr110!_write+0x90

0fdcfc04 7157081c 715e4020 00000001 0fdcfc60 msvcr110!_flush+0x37

0fdcfc14 7159d254 00000001 715e4020 715e4020 msvcr110!_ftbuf+0x1c

0fdcfc60 6e4653b9 6e478c50 0b75ceb8 d92cf0d8 msvcr110!printf+0x7f

0fdcfe08 6e4641e1 0b6ab290 0b75a040 0fdcff48 VcyAudio!CManager::GetFreeSession+0x999 [e:\workcode\vd_new\vcydialog1\src\vxiclient\vcyaudio\vcyaudio.cpp @ 1178]

0fdcff48 715959aa 0b7ebb90 daa42bbf 00000000 VcyAudio!CManager::CreateTCPThread+0x151 [e:\workcode\vd_new\vcydialog1\src\vxiclient\vcyaudio\vcyaudio.cpp @ 792]

0fdcff80 71595a6d 0fdcff94 762e33ca 0b7a2998 msvcr110!_beginthread+0xba

0fdcff88 762e33ca 0b7a2998 0fdcffd4 77939ed2 msvcr110!_endthread+0x81

0fdcff94 77939ed2 0b7a2998 7503e3e4 00000000 kernel32!BaseThreadInitThunk+0xe

0fdcffd4 77939ea5 71595a17 0b7a2998 ffffffff ntdll!__RtlUserThreadStart+0x70

0fdcffec 00000000 71595a17 0b7a2998 00000000 ntdll!_RtlUserThreadStart+0x1b

由于我的程序是x86的，而printf最终会进入系统内核，又因为其运行于x64系统上，所以还有一个wow64转换的调用堆栈，如下：

57 Id: 2024.249c Suspend: 0 Teb: 00000000`7eefe000 Unfrozen

RetAddr : Args to Child : Call Site

00000000`753df5a1 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : ntdll!ZwRequestWaitReplyPort+0xa

00000000`753ddb37 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`753df5a1 : wow64win!ConsoleClientCallServer+0x99

00000000`753b577f : 00000000`0fdce058 00000000`7540f2cd 00000000`7eefe000 00000000`7541bee8 : wow64win!WriteConsoleInternal+0x123

00000000`7540cf87 : 00000000`0fdcf730 00000000`0fdce09c 00000000`0000004f 00000000`00000000 : wow64win!whWriteConsoleInternal+0x23

00000000`75392776 : 00000000`779101c4 00000000`00000023 00000000`00000246 00000000`0fdcfff0 : wow64!Wow64SystemServiceEx+0xd7

00000000`7540d07e : 00000000`00000000 00000000`75391920 00000000`00000000 00000000`00000000 : wow64cpu!TurboDispatchJumpAddressEnd+0x2d

00000000`7540c549 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : wow64!RunCpuSimulation+0xa

00000000`7779e707 : 00000000`00000000 00000000`7efdf000 00000000`7eefe000 00000000`00000000 : wow64!Wow64LdrpInitialize+0x429

00000000`7774c32e : 00000000`0fccf820 00000000`00000000 00000000`7efdf000 00000000`00000000 : ntdll! ?? ::FNODOBFM::`string'+0x29364

00000000`00000000 : 00000000`00000000 00000000`00000000 00000000`00000000 00000000`00000000 : ntdll!LdrInitializeThunk+0xe

可见r3的printf最终会把请求通过LPC方式传递给内核，最终形成系统调用ZwRequestWaitReplyPort，但问题是，这次调用一直不会返回。

与此同时，其他调用printf的线程，都在等待着57号线程的printf完成，可57号线程一直不返回。调用堆栈如下：

58 Id: 2024.2578 Suspend: 0 Teb: 7eefa000 Unfrozen

ChildEBP RetAddr Args to Child

1052fb7c 77938dd4 00000380 00000000 00000000 ntdll!ZwWaitForSingleObject+0x15

1052fbe0 77938cb8 00000000 00000000 0b7a2998 ntdll!RtlpWaitOnCriticalSection+0x13e

1052fc08 7152ec93 715e6d28 00000000 1052fc24 ntdll!RtlEnterCriticalSection+0x150

1052fc18 71533e12 00000011 1052fc60 7159d212 msvcr110!_lock+0x31

1052fc24 7159d212 00000001 715e4020 c52a285f msvcr110!_lock_file2+0x14

1052fc60 6e4653b9 6e478c50 0b75ca80 c6a2f0d8 msvcr110!printf+0x3d

1052fe08 6e4641e1 0b6ab3a8 0b75a040 1052ff48 VcyAudio!CManager::GetFreeSession+0x999 [e:\workcode\vd_new\vcydialog1\src\vxiclient\vcyaudio\vcyaudio.cpp @ 1178]

1052ff48 715959aa 0b7ebb60 c52a2bbf 00000000 VcyAudio!CManager::CreateTCPThread+0x151 [e:\workcode\vd_new\vcydialog1\src\vxiclient\vcyaudio\vcyaudio.cpp @ 792]

1052ff80 71595a6d 1052ff94 762e33ca 0b7a2998 msvcr110!_beginthread+0xba

1052ff88 762e33ca 0b7a2998 1052ffd4 77939ed2 msvcr110!_endthread+0x81

1052ff94 77939ed2 0b7a2998 6a8de3e4 00000000 kernel32!BaseThreadInitThunk+0xe

1052ffd4 77939ea5 71595a17 0b7a2998 ffffffff ntdll!__RtlUserThreadStart+0x70

1052ffec 00000000 71595a17 0b7a2998 00000000 ntdll!_RtlUserThreadStart+0x1b

59 Id: 2024.2624 Suspend: 0 Teb: 7eef7000 Unfrozen

ChildEBP RetAddr Args to Child

1106fb7c 77938dd4 00000380 00000000 00000000 ntdll!ZwWaitForSingleObject+0x15

1106fbe0 77938cb8 00000000 00000000 0b7a2998 ntdll!RtlpWaitOnCriticalSection+0x13e

1106fc08 7152ec93 715e6d28 00000000 1106fc24 ntdll!RtlEnterCriticalSection+0x150

1106fc18 71533e12 00000011 1106fc60 7159d212 msvcr110!_lock+0x31

1106fc24 7159d212 00000001 715e4020 c47e285f msvcr110!_lock_file2+0x14

1106fc60 6e4653b9 6e478c50 0b75ccc0 c7f6f0d8 msvcr110!printf+0x3d

1106fe08 6e4641e1 0b6ab5d8 0b75a040 1106ff48 VcyAudio!CManager::GetFreeSession+0x999 [e:\workcode\vd_new\vcydialog1\src\vxiclient\vcyaudio\vcyaudio.cpp @ 1178]

1106ff48 715959aa 0b7ebb78 c47e2bbf 00000000 VcyAudio!CManager::CreateTCPThread+0x151 [e:\workcode\vd_new\vcydialog1\src\vxiclient\vcyaudio\vcyaudio.cpp @ 792]

1106ff80 71595a6d 1106ff94 762e33ca 0b7a2998 msvcr110!_beginthread+0xba

1106ff88 762e33ca 0b7a2998 1106ffd4 77939ed2 msvcr110!_endthread+0x81

1106ff94 77939ed2 0b7a2998 6bd9e3e4 00000000 kernel32!BaseThreadInitThunk+0xe

1106ffd4 77939ea5 71595a17 0b7a2998 ffffffff ntdll!__RtlUserThreadStart+0x70

1106ffec 00000000 71595a17 0b7a2998 00000000 ntdll!_RtlUserThreadStart+0x1b

60 Id: 2024.2584 Suspend: 0 Teb: 7eef4000 Unfrozen

ChildEBP RetAddr Args to Child

111afb7c 77938dd4 00000380 00000000 00000000 ntdll!ZwWaitForSingleObject+0x15

111afbe0 77938cb8 00000000 00000000 0b7a2998 ntdll!RtlpWaitOnCriticalSection+0x13e

111afc08 7152ec93 715e6d28 00000000 111afc24 ntdll!RtlEnterCriticalSection+0x150

111afc18 71533e12 00000011 111afc60 7159d212 msvcr110!_lock+0x31

111afc24 7159d212 00000001 715e4020 c462285f msvcr110!_lock_file2+0x14

111afc60 6e4653b9 6e478c50 0b75ce28 c7eaf0d8 msvcr110!printf+0x3d

111afe08 6e4641e1 0b6ab808 0b75a040 111aff48 VcyAudio!CManager::GetFreeSession+0x999 [e:\workcode\vd_new\vcydialog1\src\vxiclient\vcyaudio\vcyaudio.cpp @ 1178]

111aff48 715959aa 0b7ebba8 c4622bbf 00000000 VcyAudio!CManager::CreateTCPThread+0x151 [e:\workcode\vd_new\vcydialog1\src\vxiclient\vcyaudio\vcyaudio.cpp @ 792]

111aff80 71595a6d 111aff94 762e33ca 0b7a2998 msvcr110!_beginthread+0xba

111aff88 762e33ca 0b7a2998 111affd4 77939ed2 msvcr110!_endthread+0x81

111aff94 77939ed2 0b7a2998 6bc5e3e4 00000000 kernel32!BaseThreadInitThunk+0xe

111affd4 77939ea5 71595a17 0b7a2998 ffffffff ntdll!__RtlUserThreadStart+0x70

可见，58 59 60号线程都在等待同一个Object，而这个Object就是57号线程锁住的Object，我曾想过出现问题的时候抓取内核态dump来分析这次调用到底卡在内核的哪个位置上，但似乎x64系统并不能生成full dump。

一开始我想，这会不会是Microsoft的printf实现有bug。但仔细思考应该不是，分析如下：

0:000> da 6e478c50

6e478c50 ".carid : %s."

0:000> da 0b75ceb8

0b75ceb8 "user:18601387007&poi:113.271884,"

0b75ced8 "23.131306&program:d2sc"

57号线程卡住时，printf参数没有问题，此时一共两个参数，都没有问题，也就是我作为开发者，调用printf的方法并没有出错。

另外一点，57号线程的调用堆栈表明，这次printf请求已经进入内核，所以printf的r3实现部分应该是没有问题的，只是不知道这个请求进入内核后为什么一直完不成。即便是系统有bug，那这个bug也应该是系统内核内部的，或者真正负责完成printf实质性请求的系统其他模块。

经过大量的原理性研究后和调试验证后，我发现printf进入系统时，调用的函数ZwRequestWaitReplyPort是LPC通信函数，这个请求会被csrss.exe进程处理，也就是把字符串绘制到cmd窗口上，当它完成工作后，会调用NtReplyWaitReceivePort通知ZwRequestWaitReplyPort，说你的请求已经完成，然后发起请求的线程层层返回，printf调用完毕。目前看来卡住的地方有可能是这次LPC通信，可能这个请求csrss.exe并没有接收到，所以没有给出应答，而造成printf卡住。还有可能是csrss.exe收到了这次请求，但由于某原因，一直处于等待状态，而造成没有给出应答。

后来又发现了一个关键点，被卡住的printf，当cmd窗口获得了焦点，敲击一下回车键，printf就返回了。其他的线程printf就可以继续输出了，从这点看来，上述两种情况，应该属于后者了，也就是csrss.exe接收到了请求，但由于某种原因一直处于等待状态。

我目前分析出来的就这么多，我尝试着去重现这个问题，就是如何做才能让一次printf调用卡住，但没有找到方法，如果能重现，估计也就好解决了。实在不行估计还得调试csrss.exe了。但问题是这个进程负责了太多的功能，不仅仅为我的进程提供服务，调试csrss.exe将看到大批量的各种请求，想找到我那次printf调用的请求，估计还是很费力的。

所以，跑到这里向张老师和论坛的各位大牛求助，帮忙分析一下问题。谢谢。