Linux下，多线程程序死循环问题调试
当你的软件在某个时刻停止服务，CPU占用达到100%+，这种问题一个可能的原因是产生了死循环，假设程序某处存在潜在的死循环，并在某种条件下会引发，本文以一个示例来定位出现死循环的位置。当程序某处存在死循环，通常定位问题及缩小范围的方法是，在可疑的代码处加log，或者注释掉可疑代码，这对于容易重现问题的程序来说还好，但对于“偶尔”才会产生问题程序却很难调试，因为我们很难重现程序故障。本文所述的调
·
当你的软件在某个时刻停止服务，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 }
97
98
int CSendFile::SendFile(
const
string& pathname)
99
{
100 int n;
101 while(1)
102 {
103 n++;
104 }
105 //read file and send
现在我们定位到了出问题的代码位置，这里的循环只用来演示的。
当程序某处存在死循环，通常定位问题及缩小范围的方法是，在可疑的代码处加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 -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
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 }
97
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显示所有线程
gdb gdb>attach 2907 gdb>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 12 gdb>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_sp3 21465 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 得到线程栈
更多推荐
1
0- 0
已为社区贡献2条内容
所有评论(0)