记一次进程阻塞诊断

　　本文来自博客园，作者：T-BARBARIANS，转载请注明原文链接：https://www.cnblogs.com/t-bar/p/16626951.html 谢谢！

前言

进程在运行过程中会在执行，阻塞，就绪状态下来回切换。简单介绍下各个状态的切换原因吧。

　　从执行->阻塞，一般是进程发生某种事件，例如IO，资源申请等。

　　从阻塞->就绪，是进程等待的事件已完成，为接下来的执行做好了准备。

　　从就绪->执行，处于就绪的进程得到了系统的调度，获得了时间片，实现了该进程在CPU上的执行。

　　从执行->就绪，进程被系统调度，失去了CPU的执行权。一般是时间片使用完毕，或者被其他高优先级的进程抢占。

图 1

一、问题现象

　　如下图，程序直接卡死。。。

图 2

　　进程处于阻塞状态，所有业务线程均被阻塞，失去了CPU执行权。阻塞时长，短的时候在几十秒，长的时候长达2-3分钟，然后又自行恢复，周而复始。

　　这可是已经上线的实时业务，这不是要了开发的命了。看到这个情况，自己着急得像热锅上的蚂蚁，赶紧在家里开始着手排查。

二、排查思路

　　看到了问题的现象，可是问题的排查该从哪着手呢？

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

　　一头雾水啊，到底该从哪里着手分析呢？

　　从现实回到理论，只有进程被阻塞，未被系统调度的时候，才有可能出现所有线程的CPU使用率为0。

　　朝着这个大方向开始往下分析，那到底是什么事件，导致了所有线程被阻塞。

　　有网络IO？不，我们不是一个有大量网络请求的服务端。

　　有磁盘IO？不，线上业务流量规模不至于导致产生大量磁盘读写，而且通过iotop查看，在阻塞时，系统IO读写带宽还远远未达到磁盘IO的瓶颈。

　　内存不够啦？但是阻塞的时候查看可用内存也还有1GB以上呀。

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

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

三、问题排查

　　如何查看进程运行态相关的内核态信息呢？

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

　　比如ID为93571的进程，有如下示例的一些信息：

图 3

　　例如fd目录记录了当前进程打开的文件id，status文件记录了进程的内存使用和其它众多信息，task目录则包含了该进程及其所有子线程的信息。

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

　　但是问题来了，进程是一个多线程结构，如何查看每一个业务线程当前的内核态调用链呢？答案就是通过task目录获得想要查看的线程内核调用信息。

　　先看看task里记录的线程id：

　　再具体查看某个线程id的信息：

 　　发现了吗，上图的记录项与图三里的记录项一模一样，就是说我们也可以具体的了解到某个线程的运行态信息！比如某个业务线程的内核条调用链：

　　另外，其实只要知道了某个线程的id号，直接通过cat /proc/$[thread_id]/stack也是可以的，而不需要通过进程ID下的task查看。例如：

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

　　这确实是个问题，业务线程数量多，而且多种系统调用信息转瞬即逝，不可能一直在那不停的手动cat吧，这不跟大海捞针一样么。

　　那该如何解决呢？是时候拿出另外一个秘籍了！

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

　　操作步骤：

　　（1）准备好要记录日志的所有线程id。例如图1中的68616、68618、68620、68622、68624、68626、68628、68630、68632，一共九个业务线程。

　　（2）分别执行记录所有线程日志的命令行。注意每一个窗口执行一条命令。

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" 

　　（3）等待阻塞事件发生后，结束所有日志记录。

　　万事俱备，只欠东风。到这里，一切安排妥当，坐等阻塞上钩！说实话，还担心你不出现呢！

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

 图 4

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

　　内存真的不足了么？再次阻塞时，赶紧查看了一下系统可供用户态程序使用的内存信息：

图 5

图 6

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

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

四、解决方法

　　阻塞业务的原因找到了，业务程序的内存使用并不大，但是为什么会出现这个问题，以及如何避免这个问题呢？毕竟现网业务可不能停啊！

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

　　解决方法：

　　（1）优化了“XXX”的内存使用，某个时间点定时多任务并发执行，改为定时串行执行，降低内存开销。

　　（2）优化了自己的业务程序，尽可能的减小内存申请的大小。

　　（3）通过脚本释放buffer/cache占用内存，释放的内存会被还原到buddy管理的内存结构上，使得用户态程序可以申请到更多，更大的内存块。如上面图6所示，某个时间，buff/cache所占用的内存也非常高（buff/cache本质还是使用的物理内存，具体概念在这里就不再展开了），可以通过一个定时执行的脚本去释放这部分内存。在这也把脚本奉献给大家吧！不过需要注意，对buffer/cache的释放需要谨慎，有可能造成某些还未落盘的文件丢失，这部分还没有去考证过。

 1 #! /bin/bash
 2 
 3 # 内存使用百分比，可以传参，默认是20%
 4 log=/root/log/memory.log
 5 
 6 max_rate=$1
 7 
 8 if [ ! "$max_rate" ] ; then
 9         max_rate=20
10 fi
11 
12 #echo "max_rate: $max_rate"
13  
14 total=`free -g | awk 'NR==2' | awk '{print $2}'`
15 used=`free -g | awk 'NR==2' | awk '{print $3}'`
16 free=`free -g | awk 'NR==2' | awk '{print $4}'`
17 buffer_cache=`free -g | awk 'NR==2' | awk '{print $6}'`
18 
19 rate=$(($buffer_cache*100/$total));
20 
21 echo "===========================" >> $log
22 date >> $log
23 echo "buffer_cache_usage_rate: $rate%" >> $log
24 echo "Memory information:" >> $log
25 echo "Total: ${total}GB" >> $log
26 echo "Use: ${used}GB" >> $log
27 echo "Free: ${free}GB" >> $log
28 echo "buff_cache: ${buffer_cache}GB" >> $log
29 
30 if [ "$rate" -ge "$max_rate" ] ; then
31         echo 1 > /proc/sys/vm/drop_caches
32         echo "buffer and cache release over" >> $log
33 fi
34 
35 echo -e "===========================\n" >> $log

五、结语

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

　　技术也是不断实践积累的，在此分享出来与大家一起共勉！

　　如果文章对你有些许帮助，还请各位技术爱好者登录点赞呀，谢谢！

　　本文来自博客园，作者：T-BARBARIANS，转载请注明原文链接：https://www.cnblogs.com/t-bar/p/16626951.html 谢谢！