一次惊呆的调试经历

运行环境:基于Linux内核的嵌入式系统

编程语言:C

应用场景:两个线程A、B协同完成发送数据包工作。

定时器线程A:专门用来执行定时操作。使用一个全局的定时器队列存储定时器,定时器中包含超时时间和处理函数,一旦定时器超时就会执行处理函数。

数据监听线程B:专门用来监听数据的接收。一旦监听到数据就往全局定时器队列中添加一个定时器,该定时器处理函数所做的操作就是往网络上层发送数据包。

问题:B线程不断往A线程添加定时器,A不断执行这些定时器,现在的问题是A线程会概率性退出。

调试过程:

1.发现这个问题之前其实在查更表层的问题,最后才定位到是因为A线程退出导致。

2.这个问题自己解决不了,收集各路大牛意见,得到的答复大概是这样:这个线程太诡异,其它线程都正常,就这个线程退出,按理应该整个进程都会崩溃;感觉线程是主动退出的;从代码上看感觉没有什么问题。

3.增加了各种打印,不断重现问题,确定问题不是因为这些地方,如网络发包函数、互斥锁等,也排除了线程自身调用pthread_exit函数退出的情况(可能性最大的地方却没有出现问题,挫败感直线升级。线程异常退出是概率性事件,无疑增加调试难度)

4.无奈再次请外援

5.经大牛建议,在定时器线程中增加了n多的打印,以确定线程到底在哪个位置异常退出。值得注意的是我们在执行定时器处理函数位置处打印了处理函数的地址(处理函数并不是一致的,需要定位调用了哪个函数,此时我并不清楚如何通过函数地址来定位函数名)

6.经过不断的复现问题,确定定时器线程是在执行地址为0xcd1c的这个函数时异常退出。至于如何根据地址确定函数名,大牛给出方法如下:nm vs04pl_nostrip | grep cd1c(nm命令可以列出.o .a .so中的函数以及全局变量的地址;vs04pl_nostrip 是编译目标文件;grep 命令可以查找字符串),命令输出:

0000cd1c t $a
0052cd1c d __cint_struct_members__bcm_fabric_tdm_editing_t
001cd1c0 t $d
0000cd1c t TriggerTimerTimeoutFnc

我们一眼就定位到TriggerTimerTimeoutFnc这个函数,果然是在这里。

7.在TriggerTimerTimeoutFnc函数中增加无数打印,不断复现问题,发现线程每次都在这里退出,代码如下:

memcpy((unsigned char *)aulArgs, (unsigned char *)pArg, sizeof(aulArgs));

ulSerialNo = aulArgs[0];
ucPortNo = aulArgs[1];

一个很简单的复制内存操作,会有什么问题?既然如此,不用memcpy,直接赋值,修改如下:

ulSerialNo = ((unsigned long *)pArg)[0];
ucPortNo = ((unsigned long *)pArg)[1];

重新编译代码升级设备复现问题,发现线程依然在此处退出。(至此我已经缴械)

8.大牛若有所思的样子,在此处增加了一行代码,打印了指针pArg的地址

printf("%s %d pArg=%p ",__func__,__LINE__,pArg);

再次编译代码升级设备复现问题,发现指针pArg的所指位置为0xbdbffd00

9.ps查看进程中其它线程pid:

51 root 12608 S ./vs04pl
54 root 12608 S ./vs04pl
56 root 12608 S ./vs04pl
63 root 12608 S ./vs04pl
64 root 12608 S ./vs04pl
66 root 12608 S ./vs04pl
67 root 12608 R ./vs04pl
68 root 12608 S ./vs04pl
69 root 12608 S ./vs04pl
70 root 12608 S ./vs04pl
71 root 12608 S ./vs04pl
73 root 12608 S ./vs04pl
74 root 12608 S ./vs04pl
75 root 12608 S ./vs04pl
76 root 12608 S ./vs04pl
77 root 12608 S ./vs04pl
79 root 12608 S ./vs04pl
80 root 12608 S ./vs04pl
81 root 12608 S ./vs04pl
82 root 12608 S ./vs04pl
83 root 12608 S ./vs04pl
88 root 12608 S ./vs04pl
89 root 12608 S ./vs04pl
90 root 12608 S ./vs04pl
91 root 12608 S ./vs04pl
124 root 12608 S ./vs04pl

选定pid 80,进入/proc/80目录。

查看maps文件,线程内存空间如下(同一进程所有线程的内存空间相同):

00008000-0045b000 r-xp 00000000 00:01 149 /vs/vs04pl
00462000-00572000 rw-p 00452000 00:01 149 /vs/vs04pl
00572000-0070b000 rwxp 00572000 00:00 0 [heap]
40000000-40005000 r-xp 00000000 00:01 51 /lib/ld-uClibc-0.9.30.so
40005000-40006000 rw-p 40005000 00:00 0
4000c000-4000d000 r--p 00004000 00:01 51 /lib/ld-uClibc-0.9.30.so
4000d000-4000e000 rw-p 00005000 00:01 51 /lib/ld-uClibc-0.9.30.so
4000e000-40011000 r-xp 00000000 00:01 49 /lib/libcrypt-0.9.30.so
40011000-40018000 ---p 40011000 00:00 0
40018000-40019000 r--p 00002000 00:01 49 /lib/libcrypt-0.9.30.so
40019000-4002b000 rw-p 40019000 00:00 0
4002b000-40036000 r-xp 00000000 00:01 47 /lib/libpthread-0.9.30.so
40036000-4003d000 ---p 40036000 00:00 0
4003d000-4003e000 r--p 0000a000 00:01 47 /lib/libpthread-0.9.30.so
4003e000-40043000 rw-p 0000b000 00:01 47 /lib/libpthread-0.9.30.so
40043000-40045000 rw-p 40043000 00:00 0
40045000-40056000 r-xp 00000000 00:01 45 /lib/libm-0.9.30.so
40056000-4005d000 ---p 40056000 00:00 0
4005d000-4005e000 r--p 00010000 00:01 45 /lib/libm-0.9.30.so
4005e000-4005f000 rw-p 00011000 00:01 45 /lib/libm-0.9.30.so
4005f000-4006a000 r-xp 00000000 00:01 56 /lib/libgcc_s.so.1
4006a000-40071000 ---p 4006a000 00:00 0
40071000-40072000 rw-p 0000a000 00:01 56 /lib/libgcc_s.so.1
40072000-400ab000 r-xp 00000000 00:01 48 /lib/libuClibc-0.9.30.so
400ab000-400b2000 ---p 400ab000 00:00 0
400b2000-400b3000 r--p 00038000 00:01 48 /lib/libuClibc-0.9.30.so
400b3000-400b4000 rw-p 00039000 00:01 48 /lib/libuClibc-0.9.30.so
400b4000-400b8000 rw-p 400b4000 00:00 0
400b8000-404b8000 rw-s 83c00000 00:01 231 /dev/mem
ba7fc000-ba800000 rwxp ba7fc000 00:00 0
ba9fc000-baa00000 rwxp ba9fc000 00:00 0
babfc000-bac00000 rwxp babfc000 00:00 0
badfc000-bae00000 rwxp badfc000 00:00 0
baffc000-bb000000 rwxp baffc000 00:00 0
bb1fc000-bb200000 rwxp bb1fc000 00:00 0
bb3fc000-bb400000 rwxp bb3fc000 00:00 0
bb5fc000-bb600000 rwxp bb5fc000 00:00 0
bb7fc000-bb800000 rwxp bb7fc000 00:00 0
bb9fc000-bba00000 rwxp bb9fc000 00:00 0
bbbfc000-bbc00000 rwxp bbbfc000 00:00 0
bbdfc000-bbe00000 rwxp bbdfc000 00:00 0
bbffc000-bc000000 rwxp bbffc000 00:00 0
bc1fc000-bc200000 rwxp bc1fc000 00:00 0
bc3fc000-bc400000 rwxp bc3fc000 00:00 0
bc5fc000-bc600000 rwxp bc5fc000 00:00 0
bc7fc000-bc800000 rwxp bc7fc000 00:00 0
bc9fc000-bca00000 rwxp bc9fc000 00:00 0
bcbfc000-bcc00000 rwxp bcbfc000 00:00 0
bcdfc000-bce00000 rwxp bcdfc000 00:00 0
bcffc000-bd000000 rwxp bcffc000 00:00 0
bd1fc000-bd200000 rwxp bd1fc000 00:00 0
bd3fc000-bd400000 rwxp bd3fc000 00:00 0
bd5fc000-bd600000 rwxp bd5fc000 00:00 0
bd7fc000-bd800000 rwxp bd7fc000 00:00 0
bd9fc000-bda00000 rwxp bd9fc000 00:00 0
bddfc000-bde00000 rwxp bddfc000 00:00 0
bdffc000-be000000 rwxp bdffc000 00:00 0
be1fc000-be200000 rwxp be1fc000 00:00 0
be3fc000-be400000 rwxp be3fc000 00:00 0
be5fc000-be600000 rwxp be5fc000 00:00 0
be7fc000-be800000 rwxp be7fc000 00:00 0
befc6000-befe7000 rwxp befdf000 00:00 0 [stack]

发现指针pArg所指地址0xbdbffd00并不在线程的内存范围之内,也就是说这个pArg的地址是非法的,可是为什么呢?

10.经过跟踪发现,指针pArg的地址来源于数据监听线程B中的局部变量unsigned long aulArgs[],此处不应该用局部变量,局部变量的有效范围只在{}之内,至于这个变量何时被释放引起非法访问内存是不确定的。

至此问题解决,大牛从一个更深入的层次解决了这个问题,已拜服......

原文地址:https://www.cnblogs.com/cmoca/p/5524635.html