记一次进程阻塞诊断

  本文来自博客园,作者: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,博文严禁转载,转载必究!

posted @ 2022-08-29 10:54  T-BARBARIANS  阅读(1917)  评论(2编辑  收藏  举报