PHP常驻进程内存泄露跟踪分析

背景:下午测试同学过来反馈测试机器很卡,发了系统资源截图过来咨询,看到php进程消耗大量内存和CPU资源(top命令查看到的截图),经了解后,发现是团队的另外一名开发同学在做coupon邮件到期提醒的邮件通知业务,技术解决方案是基于php进行常驻,监听rabbitmq进行临期Coupon消息邮件发送任务;

为了不影响其他测试工作,临时先将该进程kill掉,然后再分析(当时测试机器内存不足,已经在进行swap交换,登陆到机器已经很卡了);

1. 问题分析

memleak

1.1. 了解消息消费业务,初步分析可能存在内存泄露的问题

和业务同学大致了解下,具体的业务就是通过rabbitMQ消费消息,然后从SOA进行服务调用,然后进行批量数据组装,通过邮件服务发送邮件。

一开始,还怀疑是否一次批量处理的数据过多,或者是程序中存在大量内存申请或者循环申请内存的问题,和研发一起Review下代码,MQ的消息回调是从单独函数处理,内部处理完后,会被GC回收,且内部处理函数接收消息后,一次批量发送邮件的相关数据也不是很多。另外,查看了相关RabbitMQ的预取消息数量,条数也不是很大!

这块我们先在开发机器,通过简单的php内存统计函数memory_get_usage简单分析了下,单次函数内部处理大致是使用了10M左右内存,并不是很大,而且在函数退出后,相关申请的资源会被回收!

1.2. 测试机器复现,top看到的状态

与研发同学沟通了解了情况后,我这边将他之前在测试机器跑的php的任务程序,重新跑了起来,通过top发现系统的确此时已经出现了异常,明显卡顿了起来。

其中5481进程就是该任务脚本,同时也存在大量的Swap分区交换被使用了(6g+),top如果要查看每个CPU的情况,可以输入1

top - 19:16:35 up 271 days, 11:11, 49 users,  load average: 2.99, 1.65, 1.01
Tasks: 480 total,   2 running, 466 sleeping,  12 stopped,   0 zombie
%Cpu(s): 14.7 us,  1.8 sy,  0.0 ni, 81.3 id,  2.0 wa,  0.0 hi,  0.1 si,  0.0 st
KiB Mem :  8010576 total,  2211204 free,  4108432 used,  1690940 buff/cache
KiB Swap: 16383996 total, 10104712 free,  6279284 used.  2380340 avail Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 5481 root      20   0 4752808 3.433g  75332 R  61.6 44.9   1:29.42 php
 5875 root      20   0  156116   2592   1544 R   0.7  0.0   0:00.14 top

1.3. ps查看进行执行命令为php的一个处理脚本

这次是我这边手动启动的,进行问题复现模拟(第一次排查过程也是通过该方式快速找到进程执行的相关命令,并kill掉后,测试机器恢复了正常)

[root@GearBest ~]$ ps -ef|grep 5481
root      5481  5475 52 19:13 pts/12   00:01:32 php artisan task:event --queue=userCouponExpire_GB
root      5925  5563  0 19:16 pts/20   00:00:00 grep --color=auto 5481

1.4. pidstat同步查看进程状态

执行pidstat 1发现php进程在用户态cpu使用也很高

07:44:46 PM   UID       PID    %usr %system  %guest    %CPU   CPU  Command
07:44:47 PM     0     12408    0.97    0.00    0.00    0.97     3  java
07:44:47 PM     0     5481     39.81    1.94    0.00   41.75     1  php
07:44:47 PM     0     21759    0.97    1.94    0.00    2.91     0  pidstat
07:44:47 PM  1011     31337    0.00    0.97    0.00    0.97     3  audit-engine

07:44:47 PM   UID       PID    %usr %system  %guest    %CPU   CPU  Command
07:44:48 PM   995      1087    1.00    0.00    0.00    1.00     3  mongod
07:44:48 PM     0     18080    1.00    0.00    0.00    1.00     0  supervisord
07:44:48 PM     0     5481     32.00    1.00    0.00   33.00     1  php
07:44:48 PM     0     21759    1.00    3.00    0.00    4.00     0  pidstat

1.5. vmstat查看内存相关情况

执行vmstat 1后,发现free内存持续快速减少,cache逐步增加(可能是内存泄露,也可能是程序正常申请内存),此案例中通过之前的现象已经可以往内存泄漏方面排查!

procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 2  0 5861412 3675660      0 1358372    0    0     0     0 1741  863  8  7 85  0  0
 1  0 5861412 3675692      0 1358528    0    0     0     0 2996 1086  0 25 74  0  0
 1  0 5861400 3675184      0 1358488   52    0    52     0 4485 1552  1 26 72  0  0
 0  0 5861400 3657476      0 1359396    0    0     0     0 2404  836 10  9 82  0  0
 0  0 5861396 3630224      0 1360396   20    0    20     0 1392  652 13  1 86  0  0
 0  0 5861396 3603564      0 1361396    0    0     0     0 1547  727 14  2 84  0  0
 1  0 5861396 3577988      0 1362392    0    0     0     0 1472  697 14  1 85  0  0
 1  0 5861396 3549096      0 1363396    0    0     0     0 1455  676 14  1 85  0  0
 1  0 5861392 3521288      0 1364404   32    0    32     0 1502  710 15  2 83  0  0
 1  0 5861388 3561016      0 1305728    0    0     0     0 1608  750 15  2 84  0  0
 2  0 5861388 3470260      0 1363768    0    0     0     0 1759  836 16  3 81  0  0
 1  0 5861384 3438236      0 1367536   20    0    20     0 1874  849 18  2 79  0  0
 1  0 5860932 3411332      0 1368764  284    0   284    20 1916  918 16  2 81  1  0
 1  0 5860928 3386312      0 1369768   32    0    32     0 1491  699 14  1 85  0  0
 1  0 5860916 3360052      0 1370800    4    0     4     0 1569  714 14  2 84  0  0
 1  0 5860912 3332524      0 1371844   32    0    32     0 1447  639 14  1 85  0  0
 1  0 5860904 3305584      0 1372656   32    0    32     0 1537  747 14  1 85  0  0
 1  0 5860904 3278392      0 1373696    0    0     0     0 1665  757 15  2 83  0  0

1.6. memleak工具

之前在极客时间,听性能分析时候,老师推荐使用memleak,这块尝试了下,测试服务器没有安装,需要通过yum install bcc -y安装。

另外,在使用过程中,还出现了错误,暂时先没有继续!

1.7. perf查看php进程情况

已经知道问题是php进程,可以利用perf分析进程内部调用情况。

通过perf top -g -p 5481,发现该php进程,第一个消耗最高的是newrelic,这是一个APM性能工具,到这我基本知道为什么了。

因为,前段时间我们团队在做性能优化,使用了newrelic,在测试环境和生产环境都使用了;

然后在生产环境使用几天的时间内,运维同时反馈出现过OOM,当时因为只有装了newrelic的插件的服务器会出现高CPU、高内存消耗(当时还认为newrelic这么大的品牌应该不会有这类问题),但的确在停用后是恢复正常;

连续几次OOM后,我们暂时将newrelic停止掉,与此同时,我们当时也排查到,newrelic在9.1的版本的确存在内存泄露的问题(目前升级到9.2修复了)。

因此测试环境一致没有过多关注,而且newrelic的版本是没有升级的,还是9.1版本,在跑常驻任务的时候,这块问题就凸显出来了;加上是root用户启动的,不容易被OOM机制杀掉。

有关newrelic的memleak的问题:1

1.8. 解决方法:禁用newrelic模块

在php.ini中,将newrelic关闭后,再启动消费程序,整体内存就平稳了。(另外,后续升级到9.2版本,以及设置APM的数据采集频率,开启后,资源使用基本也趋于正常化)。

2. 后记

解决完问题后,同事通过启动多个进程进行消费,整体也平稳,但每个cpu的usr占用还是比较高(平均35%左右,其实这个对php的消费程序来说也算正常,内部mq消息消费、mysql查看、soa服务调用、数据循环处理),

2.1. pidstat进一步分析

在top过程中,敲入1,查看每个cpu情况,发现软中断si%较高

利用pidstat -w -p 21901,21899,21679,21902,21900 -u 1,观测到cswch/s每个进程由接近100,同时每个php进程占用的35%的cpu

通过watch -d "cat /proc/interrupts|grep -vE '^\s+[0-9]+'",持续观测进程中断情况,发现大部分是在RES(Rescheduling interrupts)

2.2. perf工具导出workload svg图像

perf工具可以通过perf timechart -p 21901,21899 record生成相关记录,按ctrl+C结束搜集;

然后利用perf timechart -i perf.data可以生成output.svg图片,然后利用scp可以同步到本地查看;

2.3. 2.3 Linux性能分析工具收藏图谱

以上图片是Linux性能分析工具的图谱参考,经常可以反复查看(涉及网络、磁盘IO、设备驱动、文件系统、Sockets、虚拟内存、CPU任务调度、系统调用、应用程序、系统库相关内容)

3. 有关OOM的补充

以上图片是应用程序通过malloc申请一块内存资源,并往其中write操作的过程,Linux系统针对内存管理是基于虚拟内存系统进行管理,MMU通过页表(Linux支持多级页表)将虚拟内存系统和物理内存系统进行映射起来,同时还利用快表(TLB)进行相关内存性能优化,以及利用伙伴系统进行内存管理;

图示中的malloc的系统调用,操作系统不会实际申请那么大的物理内存,而是申请malloc指定大小的虚拟内存,当进程针对该虚拟内存进行读写操作,MMU在页表中检测缺页后,触发缺页中断异常,此时才会分配一个物理内存页;(Linux内存申请方式有段式存储和页式存储系统以及两者的结合段页式存储系统,页式存储系统是为了解决段式存储系统内存分配资源过大问题。)

回到OOM,Linux操作系统运行过程中在内存不足时候,会做以下事项:

  • 内存LRU从缓存释放内存,提供给需要内存的进程使用;
  • swap分区交换(如果启用了swap分区交换);
  • OOM杀死oom_score高的进程;

3.1. oom_score

针对每个进程,oom_score/proc/<pid>/oom_score)得分表示被KILL掉的可能性(得分越高,越容易被KILL),当进程消耗内存越大,该得分越高;若以root用户运行,则该得分会偏小;

/proc/[pid]/oom_score (since Linux 2.6.11)
// 得分越高,越容易被杀死
This file displays the current score that the kernel gives to this process for the purpose of selecting a process  for  the  OOM-killer.   A  higher
score means that the process is more likely to be selected by the OOM-killer.  The basis for this score is the amount of memory used by the process,
with increases (+) or decreases (-) for factors including:

* whether the process creates a lot of children using fork(2) (+);  // 进程创建很多子进程,加分,容易被杀
* whether the process has been running a long time, or has used a lot of CPU time (-); // 进程长时间运行,使用了很多CPU,减分
* whether the process has a low nice value (i.e., > 0) (+); // 低NICE值进程,容易被杀
* whether the process is privileged (-); and // 特权进程、直接硬件访问进程,减分
* whether the process is making direct hardware access (-).

The oom_score also reflects the bit-shift adjustment specified by the oom_adj setting for the process.

3.2. oom_adj

另一个防止进程被OOM KILL掉的方式是将进程的oom_adj值(/proc/<pid>/oom_adj)调低(默认是0,默认范围是[-16,+15],-17表明进程禁用OOM行为),该oom_adj值越大越容易被杀死!

另外,子进程会继承父进程的设置,且仅特权级可以更新该文件!

/proc/[pid]/oom_adj (since Linux 2.6.11)
      This file can be used to adjust the score used to select which process should be killed in an out-of-memory (OOM) situation.  The kernel  uses  this
      value  for  a bit-shift operation of the process’s oom_score value: valid values are in the range -16 to +15, plus the special value -17, which dis-
      ables OOM-killing altogether for this process.  A positive score increases the likelihood of this process being killed by the OOM-killer; a negative
      score decreases the likelihood.  The default value for this file is 0; a new process inherits its parent’s oom_adj setting.  A process must be priv-
      ileged (CAP_SYS_RESOURCE) to update this file.

4. 小结

结合之前极客时间的《Linux性能分析》学到的内容以及操作系统相关知识,有目的的完成了一次内存泄露的分析过程,同时也较为快速的找到了问题的根因;

另外,持续巩固和复习OS、Unix网络编程、数据结构与算法、Mysql等基础理论,是提升自己快速识别问题和解决问题的速度,按吴军老师说的,提升自己的基准和高度,在边界内科学地做事;

定位性能问题这块,实际上涉及的综合知识较多,涉及应用架构、应用程序开发、操作系统、计算机网络、基础服务软件的工作原理等多方面,需要逐步地基于已有的相关信息,正确的推导问题产生原因,以及进一步的缩小问题范围,直至找到问题根因。


  1. https://discuss.newrelic.com/t/php-agent-9-serious-memory-leak-issues/80863/5 ↩︎