windbg分析临界区死锁

作者: 睡在床板下 | 来源:发表于2019-01-23 09:25 被阅读0次

介绍

多线程编程中，对于资源同步导致的死锁问题，应该是开发过程中经常碰到的，同时在问题定位过程中也会花费大量的时间，这里就介绍下如何通过windbg来分析死锁问题。

资源同步

windows下资源同步的方法主要是

原子访问
临界区
读写锁
旋转锁
等待函数
事件
信号量
互斥量

其中最常用的应该是临界区了（性能开销小），所以我也是拿临界区作为分析对象，其他资源同步不在此讨论。

临界区

保证在某一时刻只有一个线程能访问数据的简便办法。在任意时刻只允许一个线程对共享资源进行访问。如果有多个线程试图同时访问临界区，那么在有一个线程进入后其他所有试图访问此临界区的线程将被挂起，并一直持续到进入临界区的线程离开。临界区在被释放后，其他线程可以继续抢占，并以此达到用原子方式操作共享资源的目的。
临界区包含两个操作原语：
EnterCriticalSection（）进入临界区
LeaveCriticalSection（）离开临界区
EnterCriticalSection（）语句执行后代码将进入临界区以后无论发生什么，必须确保与之匹配的 LeaveCriticalSection（）都能够被执行到。否则临界区保护的共享资源将永远不会被释放。虽然临界区同步速度很快，但却只能用来同步本进程内的线程，而不可用来同步多个进程中的线程。

结构体定义

typedef struct _RTL_CRITICAL_SECTION {
    PRTL_CRITICAL_SECTION_DEBUG DebugInfo;
    LONG LockCount;
    LONG RecursionCount;
    HANDLE OwningThread;
    HANDLE LockSemaphore;
    ULONG_PTR SpinCount;
} RTL_CRITICAL_SECTION, *PRTL_CRITICAL_SECTION;

各个参数的解释如下：
第一个参数：PRTL_CRITICAL_SECTION_DEBUG DebugInfo;//调试用的
第二个参数：LONG LockCount;//初始化为-1，n表示有n个线程在等待
第三个参数：LONG RecursionCount;//表示该临界区的拥有线程对此资源获得临界区次数，初为0
第四个参数：HANDLE OwningThread;//即拥有该临界区的线程句柄
第五个参数：HANDLE LockSemaphore;//实际上是一个自复位事件
第六个参数：DWORD SpinCount;//旋转锁的设置，单CPU下忽略

由这个结构可以知道：临界区会记录拥有该临界区的线程句柄，即临界区是有“线程所有权”概念的。事实上它会用第四个参数OwningThread来记录获准进入临界区的线程句柄，如果这个线程再次进入，EnterCriticalSection()会更新第三个参数RecursionCount以记录该线程进入的次数并立即返回让该线程进入。其它线程调用EnterCriticalSection()则会被切换到等待状态，一旦拥有线程所有权的线程调用LeaveCriticalSection()使其进入的次数为0时，系统会自动更新临界区并将等待中的线程换回可调度状态。

问题出现

服务器工作线程每5s会定时上报当前还有多少消息堆积未处理，正常情况应该都是<=10左右。如果出现cpu不足、io、死锁、假死等问题导致工作线程无法正常消费，那么消息堆积数量会逐渐上升。某天在告警群里面提示某服务的消息堆积从100、400、1000、3000、5000 逐渐上升，第一感觉就是服务出问题了，立刻让运维查看服务器cpu、内存、io，均正常，而且同物理主机的其他服务正常运行，所以问题应该是该服务程序出现了某些状况，可能是死锁、也可能是死循环、也可能是长时间sleep..... 立刻保存fulldump，然后重启服务，先恢复线上服务，以免给客户带来更大损失。

分析过程

下载dump

下载地址(提取码：33lg)

步骤1

使用windbg 打开dump，并设置好pdb、操作系统pdb；
使用命令 "~*kv" 显示所有线程当前的函数调用栈，效果如下（大部分省略）

0:021> ~*kv

   0  Id: 173c.16d8 Suspend: 3 Teb: 7efdd000 Unfrozen
ChildEBP RetAddr  Args to Child              
0035b6b8 775514ab 000000d0 00000000 00000000 ntdll!NtWaitForSingleObject+0x15 (FPO: [3,0,0])
0035b724 77441194 000000d0 ffffffff 00000000 KERNELBASE!WaitForSingleObjectEx+0x98 (FPO: [Non-Fpo])
0035b73c 77441148 000000d0 ffffffff 00000000 kernel32!WaitForSingleObjectExImplementation+0x75 (FPO: [Non-Fpo])
0035b750 75777be6 000000d0 ffffffff 0e9c9dd4 kernel32!WaitForSingleObject+0x12 (FPO: [Non-Fpo])
0035b7f4 75778040 0070b1b8 000000d0 00000000 sechost!ScSendResponseReceiveControls+0xea (FPO: [Non-Fpo])
0035b8a8 75778553 0035b8bc 00000000 00000001 sechost!ScDispatcherLoop+0xc2 (FPO: [Non-Fpo])
*** WARNING: Unable to verify checksum for MatchSvr.exe
0035b8c0 012432cb 0035b8cc 0035b938 012431a0 sechost!StartServiceCtrlDispatcherA+0x68 (FPO: [Non-Fpo])
0035b8dc 01218689 fc7e3c0d 00000000 00000001 MatchSvr!CNTService::StartServiceA+0x2b
0035f928 01253f2a 00000001 00708280 006ff620 MatchSvr!main+0x139 (FPO: [Non-Fpo]) (CONV: cdecl) [d:\program files (x86)\jenkins\workspace\publish_gamechannel\matchsvr\main.cpp @ 190]
0035f968 7744338a 7efde000 0035f9b4 77bf9f72 MatchSvr!__tmainCRTStartup+0xfd (FPO: [Non-Fpo]) (CONV: cdecl) [f:\dd\vctools\crt\crtw32\dllstuff\crtexe.c @ 626]
0035f974 77bf9f72 7efde000 85371315 00000000 kernel32!BaseThreadInitThunk+0xe (FPO: [Non-Fpo])
0035f9b4 77bf9f45 01253f92 7efde000 ffffffff ntdll!__RtlUserThreadStart+0x70 (FPO: [Non-Fpo])
0035f9cc 00000000 01253f92 7efde000 00000000 ntdll!_RtlUserThreadStart+0x1b (FPO: [Non-Fpo])

   1  Id: 173c.290 Suspend: 3 Teb: 7ef9f000 Unfrozen
ChildEBP RetAddr  Args to Child              
02aef948 76fa7c1d 02aef9cc 00000000 00000000 user32!NtUserGetMessage+0x15 (FPO: [4,0,0])
02aef968 0122d9ad 02aef9cc 00000000 00000000 user32!GetMessageA+0xa1 (FPO: [Non-Fpo])
02aef9ec 0124326d 00000000 00712b08 00000000 MatchSvr!CMainService::Run+0x7d (FPO: [Non-Fpo]) (CONV: thiscall) [d:\program files (x86)\jenkins\workspace\publish_gamechannel\matchsvr\service.cpp @ 65]
02aefa0c 757775a8 00000001 00712b18 00000000 MatchSvr!CNTService::ServiceMain+0xcd

步骤2

观察所有线程的函数调用。这个服务并不复杂，总共只有二十几个线程（以前分析的都是至少100个线程的dump），然后重点查看服务进程的主要工作线程（是因为工作线程不工作才导致消息堆积）。

这个服务的工作线程有4个分别是10、11、12、13，至于怎么确定的？
1、看日志。良好的编码习惯，程序中的每个线程启动、退出都会在日志中记录
2、对代码逻辑的熟悉

步骤3

切换到其中任意一个工作线程，比如10号线程
~10s
kv

0:010> ~10s
eax=00000000 ebx=03020f70 ecx=00000000 edx=00000000 esi=7fffffff edi=ffffffff
eip=77bdf8d1 esp=03bcf10c ebp=03bcf14c iopl=0         nv up ei pl zr na pe nc
cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000246
ntdll!NtWaitForSingleObject+0x15:
77bdf8d1 83c404          add     esp,4
0:010> kv
ChildEBP RetAddr  Args to Child              
03bcf10c 74a06f1f 00000330 00000001 03bcf134 ntdll!NtWaitForSingleObject+0x15 (FPO: [3,0,0])
03bcf14c 74a06d40 00000330 000001a4 00000001 mswsock!SockWaitForSingleObject+0x1ba (FPO: [Non-Fpo])
03bcf238 75796a28 000001a5 00000000 03bcf2ec mswsock!WSPSelect+0x3a6 (FPO: [Non-Fpo])
03bcf2b8 744d7787 000001a5 00000000 03bcf2ec ws2_32!select+0x494 (FPO: [Non-Fpo])
WARNING: Stack unwind information not available. Following frames may be wrong.
03bcf3f4 744d75f0 000001a4 00000004 ffffffff rabbitmq_4!amqp_open_socket+0x347
03bcf600 744d76ca 00720ae8 000021e0 ffffffff rabbitmq_4!amqp_open_socket+0x1b0
03bcf620 744d9693 00720ae8 000021e0 00000000 rabbitmq_4!amqp_open_socket+0x28a
03bcf638 744d7e26 0497bdc8 00720ae8 000021e0 rabbitmq_4!amqp_parse_url+0x3c3
03bcf650 01250550 0497bdc8 00720ae8 000021e0 rabbitmq_4!amqp_socket_open+0x16
03bcf728 01250e97 fff73d65 0070b3d8 071ca950 MatchSvr!CRabbitMQ::connect+0xd0
03bcf840 01250870 0071ecf4 0071ecc4 03bcfa28 MatchSvr!CRabbitMQ::_publish_str_+0x187
03bcf8a4 01250100 0071ecf4 0071ecc4 03bcfa28 MatchSvr!CRabbitMQ::sendmsg+0x20
03bcf908 01218d48 0071ecf4 0071ecc4 03bcfa28 MatchSvr!CRabbitmqProc::sendmsg+0x20
03bcf96c 01231fbc 03bcfa28 fff7382d 0070b3d8 MatchSvr!CProducerMQ::RabbitMQPublish_log+0x28 (FPO: [Non-Fpo]) (CONV: thiscall) [d:\program files (x86)\jenkins\workspace\publish_gamechannel\matchsvr\producermq.cpp @ 62]
03bcfd08 0122eb98 071cae70 08c6c368 007022a8 MatchSvr!CSockServer::OnGameUserArenaResult+0xc3c (FPO: [Non-Fpo]) (CONV: thiscall) [d:\program files (x86)\jenkins\workspace\publish_gamechannel\matchsvr\socksvr.cpp @ 1096]
03bcfda4 012392e4 071cae70 08c6c368 0070b3e0 MatchSvr!CSockServer::OnRequest+0x718 (FPO: [Non-Fpo]) (CONV: thiscall) [d:\program files (x86)\jenkins\workspace\publish_gamechannel\matchsvr\socksvr.cpp @ 309]
03bcfdcc 0123d1bb 00000000 00715868 007141b8 MatchSvr!CIocpWorker::DoWorkLoop+0xa4
03bcfde4 0123d18b 03bcfe24 70ffc01d 0070b3d8 MatchSvr!CBaseWorker::WorkerThreadProc+0x2b
03bcfdec 70ffc01d 0070b3d8 0d15d467 00000000 MatchSvr!CBaseWorker::WorkerThreadFunc+0xb
03bcfe24 70ffc001 00000000 03bcfe3c 7744338a msvcr120!_callthreadstartex+0x1b (FPO: [Non-Fpo]) (CONV: cdecl) [f:\dd\vctools\crt\crtw32\startup\threadex.c @ 376]
03bcfe30 7744338a 007141b8 03bcfe7c 77bf9f72 msvcr120!_threadstartex+0x7c (FPO: [Non-Fpo]) (CONV: stdcall) [f:\dd\vctools\crt\crtw32\startup\threadex.c @ 354]
03bcfe3c 77bf9f72 007141b8 86be14dd 00000000 kernel32!BaseThreadInitThunk+0xe (FPO: [Non-Fpo])
03bcfe7c 77bf9f45 70ffbfb4 007141b8 ffffffff ntdll!__RtlUserThreadStart+0x70 (FPO: [Non-Fpo])
03bcfe94 00000000 70ffbfb4 007141b8 00000000 ntdll!_RtlUserThreadStart+0x1b (FPO: [Non-Fpo])

从中，我们看到调用栈并没有什么问题，大概意思就是收到了一个GameUserArenaResult消息，然后通过mq publish出去，然后mq模块正在进行connect。感觉没有问题，接着看11号线程

~11s
kv

0:010> ~11s
eax=00000001 ebx=00000000 ecx=00000000 edx=00000000 esi=007124f8 edi=00000000
eip=77bdf8d1 esp=03ccf4cc ebp=03ccf530 iopl=0         nv up ei pl zr na pe nc
cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000246
ntdll!NtWaitForSingleObject+0x15:
77bdf8d1 83c404          add     esp,4
0:011> kv
ChildEBP RetAddr  Args to Child              
03ccf4cc 77bf8e44 00000e0c 00000000 00000000 ntdll!NtWaitForSingleObject+0x15 (FPO: [3,0,0])
03ccf530 77bf8d28 00000000 00000000 0070b3e0 ntdll!RtlpWaitOnCriticalSection+0x13e (FPO: [Non-Fpo])
03ccf558 01216e48 007124f8 0070b3d8 030c7658 ntdll!RtlEnterCriticalSection+0x150 (FPO: [Non-Fpo])
03ccf5b4 0121525e 0070b3d8 030c7658 0070b3e0 MatchSvr!JMutex::Lock+0x28 (FPO: [Non-Fpo]) (CONV: thiscall) [d:\program files (x86)\jenkins\workspace\publish_gamechannel\matchsvr\jmutex.cpp @ 71]
03ccf60c 01214b6a 007124f8 ff873359 0070b3d8 MatchSvr!JMutexAutoLock::JMutexAutoLock+0x1e (FPO: [Non-Fpo]) (CONV: thiscall) [d:\program files (x86)\jenkins\workspace\publish_gamechannel\matchsvr\jmutexautolock.h @ 39]
03ccf67c 01231c00 03ccf790 ff873f3d 0070b3d8 MatchSvr!CDelaySendMsg::AddMsg+0x3a (FPO: [Non-Fpo]) (CONV: thiscall) [d:\program files (x86)\jenkins\workspace\publish_gamechannel\matchsvr\delaysendmsg.cpp @ 14]
03ccfa18 0122eb98 05ebbe68 088d7790 00702348 MatchSvr!CSockServer::OnGameUserArenaResult+0x880 (FPO: [Non-Fpo]) (CONV: thiscall) [d:\program files (x86)\jenkins\workspace\publish_gamechannel\matchsvr\socksvr.cpp @ 1071]
03ccfab4 012392e4 05ebbe68 088d7790 0070b3e0 MatchSvr!CSockServer::OnRequest+0x718 (FPO: [Non-Fpo]) (CONV: thiscall) [d:\program files (x86)\jenkins\workspace\publish_gamechannel\matchsvr\socksvr.cpp @ 309]
03ccfadc 0123d1bb 00000000 00715ff8 007154a0 MatchSvr!CIocpWorker::DoWorkLoop+0xa4
03ccfaf4 0123d18b 03ccfb34 70ffc01d 0070b3d8 MatchSvr!CBaseWorker::WorkerThreadProc+0x2b
03ccfafc 70ffc01d 0070b3d8 0d65d177 00000000 MatchSvr!CBaseWorker::WorkerThreadFunc+0xb
03ccfb34 70ffc001 00000000 03ccfb4c 7744338a msvcr120!_callthreadstartex+0x1b (FPO: [Non-Fpo]) (CONV: cdecl) [f:\dd\vctools\crt\crtw32\startup\threadex.c @ 376]
03ccfb40 7744338a 007154a0 03ccfb8c 77bf9f72 msvcr120!_threadstartex+0x7c (FPO: [Non-Fpo]) (CONV: stdcall) [f:\dd\vctools\crt\crtw32\startup\threadex.c @ 354]
03ccfb4c 77bf9f72 007154a0 86ce112d 00000000 kernel32!BaseThreadInitThunk+0xe (FPO: [Non-Fpo])
03ccfb8c 77bf9f45 70ffbfb4 007154a0 ffffffff ntdll!__RtlUserThreadStart+0x70 (FPO: [Non-Fpo])
03ccfba4 00000000 70ffbfb4 007154a0 00000000 ntdll!_RtlUserThreadStart+0x1b (FPO: [Non-Fpo])

这个堆栈就有意思了，大概就是收到了OnGameUserArenaResult消息，然后AddMsg，进入一个AutoLock，然后RtlEnterCriticalSection，看到这个说明很可能有死锁问题。我们继续观察这个临界区的具体信息

03ccf558 01216e48 007124f8 0070b3d8 030c7658 ntdll!RtlEnterCriticalSection+0x150 (FPO: [Non-Fpo])

注意其中的第三列、第四列、第五列，分别代表了这个函数的第一个入参、第二个入参、第三个入参，之前看过临界区的结构体，所以使用以下命令

!cs 007124f8

0:011> !cs 007124f8
-----------------------------------------
Critical section   = 0x007124f8 (+0x7124F8)
DebugInfo          = 0x007184b8
LOCKED
LockCount          = 0x2
WaiterWoken        = No
OwningThread       = 0x00001188
RecursionCount     = 0x1
LockSemaphore      = 0xE0C
SpinCount          = 0x00000000

这个临界区正在被 0x00001188 的线程占用，所以导致11s线程无法进入临界区，那么我们就去 0x00001188 线程在做什么。
通过线程id显示线程号命令
~~[0x00001188]

0:011> ~~[0x00001188]
   4  Id: 173c.1188 Suspend: 3 Teb: 7ef96000 Unfrozen
      Start: msvcr120!_threadstartex (70ffbfb4) 
      Priority: 0  Priority class: 32  Affinity: 3

4号线程，然后我们切换
~4s
kv

0:004> kv
ChildEBP RetAddr  Args to Child              
02fdf4b0 77bf8e44 00000dcc 00000000 00000000 ntdll!NtWaitForSingleObject+0x15 (FPO: [3,0,0])
02fdf514 77bf8d28 00000000 00000000 00713298 ntdll!RtlpWaitOnCriticalSection+0x13e (FPO: [Non-Fpo])
02fdf53c 01253666 00720b68 00000000 00713df0 ntdll!RtlEnterCriticalSection+0x150 (FPO: [Non-Fpo])
02fdf598 0125232e 00000000 00713df0 00713298 MatchSvr!CJMutex::Lock+0x26
02fdf5f0 01250d6a 00720b68 feb63229 00000000 MatchSvr!CJAutoLock::CJAutoLock+0x1e
02fdf70c 01250870 0071ecf4 0071ecdc 061b729c MatchSvr!CRabbitMQ::_publish_str_+0x5a
02fdf770 01250100 0071ecf4 0071ecdc 061b729c MatchSvr!CRabbitMQ::sendmsg+0x20
02fdf7d4 01218d88 0071ecf4 0071ecdc 061b729c MatchSvr!CRabbitmqProc::sendmsg+0x20
02fdf838 01214ccd 061b729c feb63ded 00000000 MatchSvr!CProducerMQ::RabbitMQPublish_Award+0x28 (FPO: [Non-Fpo]) (CONV: thiscall) [d:\program files (x86)\jenkins\workspace\publish_gamechannel\matchsvr\producermq.cpp @ 72]
02fdf8c8 012172b9 00000000 00713df0 00713298 MatchSvr!CDelaySendMsg::Thread+0x11d (FPO: [Non-Fpo]) (CONV: thiscall) [d:\program files (x86)\jenkins\workspace\publish_gamechannel\matchsvr\delaysendmsg.cpp @ 46]
02fdf924 70ffc01d 007124a0 0c54d31f 00000000 MatchSvr!JThread::TheThread+0x39 (FPO: [Non-Fpo]) (CONV: stdcall) [d:\program files (x86)\jenkins\workspace\publish_gamechannel\matchsvr\jthread.cpp @ 175]
02fdf95c 70ffc001 00000000 02fdf974 7744338a msvcr120!_callthreadstartex+0x1b (FPO: [Non-Fpo]) (CONV: cdecl) [f:\dd\vctools\crt\crtw32\startup\threadex.c @ 376]
02fdf968 7744338a 00713298 02fdf9b4 77bf9f72 msvcr120!_threadstartex+0x7c (FPO: [Non-Fpo]) (CONV: stdcall) [f:\dd\vctools\crt\crtw32\startup\threadex.c @ 354]
02fdf974 77bf9f72 00713298 87ff1315 00000000 kernel32!BaseThreadInitThunk+0xe (FPO: [Non-Fpo])
02fdf9b4 77bf9f45 70ffbfb4 00713298 ffffffff ntdll!__RtlUserThreadStart+0x70 (FPO: [Non-Fpo])
02fdf9cc 00000000 70ffbfb4 00713298 00000000 ntdll!_RtlUserThreadStart+0x1b (FPO: [Non-Fpo])

4号线程MQ正在publish一个消息，而这个消息中有一个临界区，这个临界区可能又正在被其他线程占用。继续查看临界区

0:004> !cs 00720b68 
-----------------------------------------
Critical section   = 0x00720b68 (+0x720B68)
DebugInfo          = 0x0071e070
LOCKED
LockCount          = 0x3
WaiterWoken        = No
OwningThread       = 0x00001590
RecursionCount     = 0x2
LockSemaphore      = 0xDCC
SpinCount          = 0x00000000

这个临界区正在被0x00001590 线程占用，再看看这个线程号是多少
~~[0x00001590]

0:004> ~~[0x00001590]
  10  Id: 173c.1590 Suspend: 3 Teb: 7ef81000 Unfrozen
      Start: msvcr120!_threadstartex (70ffbfb4) 
      Priority: 0  Priority class: 32  Affinity: 3

？？？？怎么又回到10号线程了，再仔细看看10s线程
之前我们看的时候觉的没问题，但这里肯定是有问题的，会不会'connect' 阻塞了呢? 带着疑问查看了下消息堆积时段的日志，有MQ断开的日志。带着猜测自己重现现场试试看，在本地启动服务，然后重启mq服务，发现问题必现。
解决方法就是使用非阻塞式的connect函数，问题解决。

总结

这里介绍了几个windbg的常用命令，讲解了死锁的一般分析方法，对于这类问题更多的是观察、思考。希望能带给你帮助，如果觉的有用，请帮忙打赏下吧！后续还有一些有意思的dump来分享，比如内存泄漏、死锁+崩溃、踩内存、高cpu等。现在的dump素材没有以前的多了，不然我可以把很多案例都写出来，有些问题没有案例还是挺难讲的。

windbg分析临界区死锁

介绍

资源同步

临界区

结构体定义

问题出现

分析过程

下载dump

步骤1

步骤2

步骤3

总结

相关文章

网友评论

延伸阅读

深度阅读

栏目导航

热点阅读