进程阻塞诊断详解 - 51Testing软件测试论坛

　　首先怀疑了自己的业务代码里是否有长时间的业务处理流程。可是就算是有长时间的业务处理，所有线程的cpu不可能都为零呀；其次，难道业务代码里有锁，产生了竞争？不，我们的业务代码里没有互斥使用的对象，也就没有锁。即使有锁，那也至少有一个线程cpu不为0，而且不可能这样长时间为0。

　　机器坏啦？哈哈哈，在实在没有思路的时候，真的出现过这种想法。可是经验告诉我，不到万不得已，怀疑啥都别怀疑系统，甚至怀疑硬件，必定是自己的业务代码问题，或者是某些方法使用不当带来的问题。

　　那到底是啥导致了所有业务线程的阻塞？这里可以确定的是，线程被阻塞，一定是有事件导致的阻塞。用户态可能性不大，那很有可能是系统调用阻塞在了内核态，那有没有该进程对应的内核态相关信息呢，从哪里看呢？

　　Linux其实很完备啊，Linux内核提供了pro 文件系统，系统中当前运行的每一个进程在proc下都有一个对应的目录，且以进程的PID号为目录名，用户可以通过进程对应的PID目录得到对应进程的相关运行态信息。

　　那哪个文件记录了进程当前的系统调用链呢？那就是我要找的stack文件，stack会记录当前进程在内核的调用栈，且是实时更新的！打开文件，会有某个进程当前在内核态的调用链信息，比如：

到这里，查看每一个业务线程对应的实时系统调用链的方法知道了，但是第二个问题来了：并行的业务线程很多，我怎么才能捕获到某个线程阻塞发生时的调用链信息？

　　日志是个好东西，通过watch和cat命令配合实现，一个记录时间，一个记录调用信息，不断的向日志文件追加信息。没错，就是实时记录所有业务线程的内核调用链信息，在阻塞发生后，再在日志中查看线程被阻塞对应时间段的系统调用链！

<font size="3">watch -n 1 "date '+%Y-%m-%d %H:%M:%S' >> /root/68616.log;cat /proc/68616/stack >> /root/68616.log"
watch -n 1 "date '+%Y-%m-%d %H:%M:%S' >> /root/68618.log;cat /proc/68618/stack >> /root/68618.log"
watch -n 1 "date '+%Y-%m-%d %H:%M:%S' >> /root/68620.log;cat /proc/68620/stack >> /root/68620.log"
watch -n 1 "date '+%Y-%m-%d %H:%M:%S' >> /root/68622.log;cat /proc/68622/stack >> /root/68622.log"
watch -n 1 "date '+%Y-%m-%d %H:%M:%S' >> /root/68624.log;cat /proc/68624/stack >> /root/68624.log"
watch -n 1 "date '+%Y-%m-%d %H:%M:%S' >> /root/68626.log;cat /proc/68626/stack >> /root/68626.log"
watch -n 1 "date '+%Y-%m-%d %H:%M:%S' >> /root/68628.log;cat /proc/68628/stack >> /root/68628.log"
watch -n 1 "date '+%Y-%m-%d %H:%M:%S' >> /root/68630.log;cat /proc/68630/stack >> /root/68630.log"
watch -n 1 "date '+%Y-%m-%d %H:%M:%S' >> /root/68632.log;cat /proc/68632/stack >> /root/68632.log"</font>

复制代码

　　不出所料，当业务线程再次阻塞时，非常急切的打开了记录的日志信息！9个线程，有8个都在同一时间段打印了相同的调用链（卡住了），另外一个业务线程也是在这段时间出现了非常关键的，与众不同的调用信息：　

　　alloc_pages_vma，do_try_to_free_pages，xfs_buf_iowait，是什么意思？这是在向系统请求内存分配啊，且最后内存分配出现了等待，而且都走到让buff/cache模块去释放内存了，这不就是线程阻塞的真相么！找到这样的关键信息真是欣喜万分!

可用内存真的不多了，只有300MB+，而且这300MB会通过buddy算法拆分为很多小块内存，并不是一个完整连续的空间。另外一个非常重要的信息是：阻塞时，系统无法满足应用程序向系统申请一个大于32KB的内存块。

　　好了，终于真相大白了！我的业务线程在内存不足时向系统申请了一个比较大，可能超过32KB的内存，但是此时内存池（tcmalloc）无法提供该内存块大小，向系统申请内存时应该进行了加锁，导致了其它线程全部阻塞，然后申请内存的线程又长时间得不到返回，就出现了文章开头提到的长时间阻塞，问题终于找到了！

　　在后来的调查中，发现了造成程序阻塞的背后真凶。我们系统里另外一个业务程序“XXX”，会定时大量计算某些内容，存在内存开销冲高现象，同时导致系统供用户态程序使用的内存急剧下降。若某程序此时刚好碰上稍微大一点的内存申请，那就会因为内存不够而直接阻塞。

　　（3）通过脚本释放buffer/cache占用内存，释放的内存会被还原到buddy管理的内存结构上，使得用户态程序可以申请到更多，更大的内存块。如上面图5所示，某个时间，buff/cache所占用的内存也非常高（buff/cache本质还是使用的物理内存，具体概念在这里就不再展开了），可以通过一个定时执行的脚本去释放这部分内存。

<font size="3">#! /bin/bash
# 内存使用百分比，可以传参，默认是20%
log_dir=/root/log
if [ ! -d ${log_dir} ]; then
sudo mkdir -p ${log_dir}
fi
log=/root/log/memory.log
max_rate=$1
if [ ! "$max_rate" ] ; then
max_rate=20
fi
#echo "max_rate: $max_rate"
total=`free -g | awk 'NR==2' | awk '{print $2}'`
used=`free -g | awk 'NR==2' | awk '{print $3}'`
free=`free -g | awk 'NR==2' | awk '{print $4}'`
buffer_cache=`free -g | awk 'NR==2' | awk '{print $6}'`
rate=$(($buffer_cache*100/$total));
echo "===========================" >> $log
date >> $log
echo "buffer_cache_usage_rate: $rate%" >> $log
echo "Memory information:" >> $log
echo "Total: ${total}GB" >> $log
echo "Use: ${used}GB" >> $log
echo "Free: ${free}GB" >> $log
echo "buff_cache: ${buffer_cache}GB" >> $log
if [ "$rate" -ge "$max_rate" ] ; then
echo 1 > /proc/sys/vm/drop_caches
echo "buffer and cache release over" >> $log
fi
echo -e "===========================\n" >> $log</font>

复制代码

　　为了诊断一个线上业务阻塞问题，就像中医一样经历了“望闻问切”四个过程，望（看到了进程阻塞），闻（IO？内存不足？硬件损坏？），问（此类问题的病理范围是什么？确定排查方向：看内核信息），切（把脉出是系统调用阻塞，且是内存不足引起），胸有成竹后，开了处方，来了个对症下药，最后彻底治愈。