记一次进程阻塞诊断
本文来自博客园，作者：T-BARBARIANS，博文严禁转载，转载必究！
前言
进程在运行过程中会在执行，阻塞，就绪状态下来回切换。简单介绍下各个状态的切换原因吧。
从执行->阻塞，一般是进程发生某种事件，例如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 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管理的内存结构上，使得用户态程序可以申请到更多，更大的内存块。如上面图5所示，某个时间，buff/cache所占用的内存也非常高（buff/cache本质还是使用的物理内存，具体概念在这里就不再展开了），可以通过一个定时执行的脚本去释放这部分内存。
在这也把脚本奉献给大家吧！不过需要注意，对buffer/cache的释放需要谨慎，有可能造成某些还未落盘的文件丢失，这部分还没有去考证过。
1 #! /bin/bash 2 3 # 内存使用百分比，可以传参，默认是20% 4 5 log_dir=/root/log 6 7 if [ ! -d ${log_dir} ]; then 8 sudo mkdir -p ${log_dir} 9 fi 10 11 log=/root/log/memory.log 12 13 max_rate=$1 14 15 if [ ! "$max_rate" ] ; then 16 max_rate=20 17 fi 18 19 #echo "max_rate: $max_rate" 20 21 total=`free -g | awk 'NR==2' | awk '{print $2}'` 22 used=`free -g | awk 'NR==2' | awk '{print $3}'` 23 free=`free -g | awk 'NR==2' | awk '{print $4}'` 24 buffer_cache=`free -g | awk 'NR==2' | awk '{print $6}'` 25 26 rate=$(($buffer_cache*100/$total)); 27 28 echo "===========================" >> $log 29 date >> $log 30 echo "buffer_cache_usage_rate: $rate%" >> $log 31 echo "Memory information:" >> $log 32 echo "Total: ${total}GB" >> $log 33 echo "Use: ${used}GB" >> $log 34 echo "Free: ${free}GB" >> $log 35 echo "buff_cache: ${buffer_cache}GB" >> $log 36 37 if [ "$rate" -ge "$max_rate" ] ; then 38 echo 1 > /proc/sys/vm/drop_caches 39 echo "buffer and cache release over" >> $log 40 fi 41 42 echo -e "===========================\n" >> $log
五、结语
为了诊断一个线上业务阻塞问题，就像中医一样经历了“望闻问切”四个过程，望（看到了进程阻塞），闻（IO？内存不足？硬件损坏？），问（此类问题的病理范围是什么？确定排查方向：看内核信息），切（把脉出是系统调用阻塞，且是内存不足引起），胸有成竹后，开了处方，来了个对症下药，最后彻底治愈。
技术也是不断实践积累的，在此分享出来与大家一起共勉！
如果文章对你有些许帮助，还请各位技术爱好者登录点赞呀，谢谢！
本文来自博客园，作者：T-BARBARIANS，博文严禁转载，转载必究！
