实习点滴 - 跟一个蠢bug学习多线程调试、线程安全和可重入函数

昨天同事帮忙review代码的时候，发现我代码里使用了一个非线程安全的函数localtime，并建议我使用线程安全的localtime_r。

于是我查了一下相关资料：

time 与 gettimeofday 两个函数得到的都是从Epoch开始（1970-1-1, 00:00:00）到当前的秒数(tt=tv.tv_sec)，而后者还能得到更精细的微秒级结果，即tv_sec*(10^6)+tv_usec为从Epoch开始到当前的微秒数。

localtime函数：将时间数值变换成本地时间，考虑到本地时区和夏令时标志;

struct tm *localtime(const time_t *timep);

struct tm *localtime_r(const time_t *timep, struct tm *result);

localtime是直接返回strcut tm*指针（如果成功的话），这个指针是指向一个静态变量的；因此，返回的指针所指向的静态变量有可能被其他地方调用的localtime改掉，例如多线程使用的时候。

localtime_r则是由调用者在第二个参数传入一个struct tm result指针，该函数会把结果填充到这个传入的指针所指内存里面；成功的返回值指针也就是struct tm result。

其他的时间函数，如asctime，asctime_r；ctime，ctime_r；gmtime，gmtime_r都是类似的，所以，时间函数的 _r 版本都是线程安全的。

改这个实在太简单了，没想到在这里付出了沉重的代价。

原来的代码：

    struct tm *p;
    p = localtime(&timep);

修改后的代码：

    struct tm *p = NULL;
    localtime_r(&timep, p); 

编译通过后，以为就万事大吉了，接下来发布测试，却得不到响应，查看服务器提示信息：

[alarm] zombie process,no keep alive msg for 60 seconds

竟然僵死了？？

由于这次的代码里除了以上的修改，还改了其他地方，所以一开始我以为是其他地方出了问题，完全没有怀疑是localtime_r的问题，所以对其他地方进行了测试、代码review。

折腾了半个下午，毫无进展，于是决定分段测试，先只修改localtime_r，不改其他地方，以定位问题所在。结果发现只修改了localtime_r也发生了僵死，才把目标锁定在这里了。

真相只有一个——localtime_r死锁了。

这很新奇，localtime_r不就是专门服务于多线程的吗，为什么反而导致死锁？

百思不得其解，把这个问题抛给了同事，同事说，你看到的也许只是表象，建议你看一下堆栈，查一查死锁在哪里了。

这一下子击中了我的软肋——其实我一开始就应该这样做的。

而为什么说是软肋呢，因为我一开始当然也想用gdb来调试看一看问题所在，可是我完全没有试过调试多线程的程序，根本不知道怎么下手——然后就躲在自己的舒适圈里面，继续用“打印日志”、“裸眼debug”等以前在学校惯用的方法来调试。

走投无路，还是要走出舒适圈，google了几篇多线程调试的文章，发现其实也不是很难——并且这个方法很快就帮助我定位到了问题的根源。

方法如下：

1.运行服务程序，并向该服务发送请求，使其执行相应函数进入死锁的地方。

2.查找进程id

$ ps -aux| grep "PNGBusiOp"

得到pid为9883

3.启动gdb，attach进程

$ gdb PNGBusiOpServer 9883

(gdb) info threads //显示所有线程信息
  33 Thread 0x7f5c1bee5700 (LWP 9884)  0x00007f5c1d2db98e in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  32 Thread 0x7f5c1b6e4700 (LWP 9885)  0x00007f5c1d2db98e in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  31 Thread 0x7f5c19edc700 (LWP 9886)  0x00007f5c1d2db98e in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  30 Thread 0x7f5c196db700 (LWP 9887)  0x00007f5c1d2db98e in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  29 Thread 0x7f5c18eda700 (LWP 9888)  0x00007f5c1d2db98e in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  28 Thread 0x7f5c13fff700 (LWP 9889)  0x00007f5c1c884ef3 in epoll_wait () from /lib64/libc.so.6
  27 Thread 0x7f5c137fe700 (LWP 9890)  0x00007f5c1d2db98e in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  26 Thread 0x7f5c12ffd700 (LWP 9891)  0x00007f5c1c89405e in __lll_lock_wait_private () from /lib64/libc.so.6
  25 Thread 0x7f5c127fc700 (LWP 9892)