Linux下，多线程程序死循环问题调试

来源：互联网发布：淘宝店铺打折工具编辑：程序博客网时间：2024/05/16 17:25

当你的软件在某个时刻停止服务，CPU占用达到100%+，这种问题一个可能的原因是产生了死循环，假设程序某处存在潜在的死循环，并在某种条件下会引发，本文以一个示例来定位出现死循环的位置。
当程序某处存在死循环，通常定位问题及缩小范围的方法是，在可疑的代码处加log，或者注释掉可疑代码，这对于容易重现问题的程序来说还好，但对于“偶尔”才会产生问题程序却很难调试，因为我们很难重现程序故障。本文所述的调试过程正是在这种情况下，假设问题已经出现，我们要求环境保护现场，即出问题的程序还在运行中。

1.我们首先要知道是哪个线程出了问题：
首先查一下出问题进程的pid，例如

ovtsvn@ovtsvn:~/MASS4/src/icdn/src$ ps -ef | grep icdn

ovtsvn 11065 1 50 11:57 ? 00:00:07 ./icdn

ovtsvn 11076 10971 0 11:57 pts/2 00:00:00 grep icdn

ovtsvn@ovtsvn:~/MASS4/src/icdn/src$

然后top命令查看线程信息：
top -H -p 11065

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND

11073 ovtsvn 25 0 325m 3980 2236 R 100 0.4 1:40.84 icdn

11065 ovtsvn 18 0 325m 3980 2236 S 0 0.4 0:00.01 icdn

11066 ovtsvn 18 0 325m 3980 2236 S 0 0.4 0:00.00 icdn

11067 ovtsvn 15 0 325m 3980 2236 S 0 0.4 0:00.00 icdn

11068 ovtsvn 15 0 325m 3980 2236 S 0 0.4 0:00.00 icdn

11069 ovtsvn 18 0 325m 3980 2236 S 0 0.4 0:00.00 icdn

11070 ovtsvn 18 0 325m 3980 2236 S 0 0.4 0:00.00 icdn

11071 ovtsvn 22 0 325m 3980 2236 S 0 0.4 0:00.00 icdn

11072 ovtsvn 15 0 325m 3980 2236 R 0 0.4 0:00.00 icdn

从上面可以看出，出问题线程PID为11073

2.接下来，我们用gdb来attach目标进程
执行: gdb icdn 11065
在gdb中，列出线程状态：

(gdb) info threads

9 Thread 47056948181264 (LWP 11066) 0x00002acc4a3dec91 in nanosleep () from /lib/libc.so.6

8 Thread 47056956573968 (LWP 11067) 0x00002acc4a406fc2 in select () from /lib/libc.so.6

7 Thread 47056964966672 (LWP 11068) 0x00002acc4a3dec91 in nanosleep () from /lib/libc.so.6

6 Thread 47056973359376 (LWP 11069) 0x00002acc4a3dec91 in nanosleep () from /lib/libc.so.6

5 Thread 47056981752080 (LWP 11070) 0x00002acc4a3dec91 in nanosleep () from /lib/libc.so.6

4 Thread 47056990144784 (LWP 11071) 0x00002acc4a40e63c in recvfrom () from /lib/libc.so.6

3 Thread 47057194060048 (LWP 11072) 0x00002acc4a406fc2 in select () from /lib/libc.so.6

2 Thread 47057226893584 (LWP 11073) CSendFile::SendFile (this=0x2acc5d4aff40, pathname=@0x2acc5d4afee0)

at ../src/csendfile.cpp:101

1 Thread 47056939784832 (LWP 11065) 0x00002acc4a3dec91 in nanosleep () from /lib/libc.so.6

(gdb)

gdb已经列出了各线程正在执行的函数，我们需要更多信息，记住11073对应的行首标号，这是gdb为线程分配的id，这里为2，然后执行切换：

(gdb) thread 2

[Switching to thread 2 (Thread 47057226893584 (LWP 11073))]#0 CSendFile::SendFile (this=0x2acc5d4aff40, pathname=@0x2acc5d4afee0)

at ../src/csendfile.cpp:101

101 while(1)

(gdb)

bt一下：

(gdb) bt

#0 CSendFile::SendFile (this=0x2acc5d4aff40, pathname=@0x2acc5d4afee0) at ../src/csendfile.cpp:101

#1 0x000000000040592e in CIcdn::TaskThread (pParam=0x7fff617eafe0) at ../src/cicdn.cpp:128

#2 0x00002acc4a90b73a in start_thread () from /lib/libpthread.so.0

#3 0x00002acc4a40d6dd in clone () from /lib/libc.so.6

#4 0x0000000000000000 in ?? ()

来看一下101行的代码：

(gdb) l

96 }

98 int CSendFile::SendFile(const string& pathname)

99 {

100 int n;

101 while(1)

102 {

103 n++;

104 }

105 //read file and send

现在我们定位到了出问题的代码位置，这里的循环只用来演示的。

最后别忘了detach

/**************************************************************************************************/

确定是CPU过高

使用top观察是否存在CPU使用率过高现象

找出线程

对CPU使用率过高的进程的所有线程进行排序

ps H -e -o pid,tid,pcpu,cmd --sort=pcpu |grep xxx

得到如下结果,其中线程2909使用了7.8%的CPU.

2907 2913 0.0 ./xxx

2907 2909 7.8 ./xxx

也可以通过查看/proc中的信息来确定高CPU线程. 打印了4列,线程ID,线程名,用户时间和内核时间(排名未分先后)

awk '{print $1,$2,$14,$15}' /proc/2907/task/*/stat

找出调用栈

使用gdb attach nmsagent所在的进程,在gdb中使用 info threads显示所有线程

gdbgdb>attach 2907gdb>info threads

得到如下结果,可以发现2909线程的编号是12

  13 Thread 0xad5f2b70 (LWP 2908)  0x004ef0d7 in mq_timedreceive () from /lib/tls/i686/cmov/librt.so.1  12 Thread 0xad58eb70 (LWP 2909)  0x006e0422 in __kernel_vsyscall ()  11 Thread 0xad52ab70 (LWP 2910)  0x006e0422 in __kernel_vsyscall ()  10 Thread 0xad4f8b70 (LWP 2911)  0x006e0422 in __kernel_vsyscall ()  9 Thread 0xad4c6b70 (LWP 2912)  0x006e0422 in __kernel_vsyscall ()  8 Thread 0xad3feb70 (LWP 2913)  0x004ef0d7 in mq_timedreceive () from /lib/tls/i686/cmov/librt.so.1  7 Thread 0xace08b70 (LWP 2914)  0x004ef0d7 in mq_timedreceive () from /lib/tls/i686/cmov/librt.so.1  6 Thread 0xac607b70 (LWP 2915)  0x006e0422 in __kernel_vsyscall ()  5 Thread 0xac5e6b70 (LWP 2916)  0x006e0422 in __kernel_vsyscall ()  4 Thread 0xac361b70 (LWP 2917)  0x006e0422 in __kernel_vsyscall ()  3 Thread 0xac2fdb70 (LWP 2918)  0x006e0422 in __kernel_vsyscall ()  2 Thread 0xac1fcb70 (LWP 2919)  0x004ef0d7 in mq_timedreceive () from /lib/tls/i686/cmov/librt.so.1* 1 Thread 0xb78496d0 (LWP 2907)  0x006e0422 in __kernel_vsyscall ()

使用thread 切换线程,使用bt显示线程栈

gdb>thread 12gdb>bt

得到如下线程栈

#0  0x006e0422 in __kernel_vsyscall ()#1  0x001cca26 in nanosleep () from /lib/tls/i686/cmov/libc.so.6#2  0x001fc2dc in usleep () from /lib/tls/i686/cmov/libc.so.6#3  0x0806b510 in OspTaskDelay ()#4  0x0805c710 in CDispatchTask::NodeMsgSendToSock() ()#5  0x0805cc74 in DispatchTaskEntry ()#6  0x0806a8e9 in OspTaskTemplateFunc(void*) ()#7  0x00d4780e in start_thread () from /lib/tls/i686/cmov/libpthread.so.0 #8  0x002027ee in clone () from /lib/tls/i686/cmov/libc.so.6

ps + strace

得到进程ID 21465

ps -e |grep cmu 4996 ?        00:00:25 cmu_fjga_sp321465 pts/5    00:08:10 cmu

得到线程时间, 其中最占CPU的是 EpollRecvTask 21581

ps -eL |grep 21465

21465 21579 pts/5 00:00:00 CamApp

21465 21580 pts/5 00:00:00 TimerMan Task

21465 21581 pts/5 00:09:02 EpollRecvTask

21465 21582 pts/5 00:00:00

使用 strace -p 21581 得到线程栈

0 0