分类： 性能优化

收到报警, Postgresql数据库服务器出现瞬时CPU占用高峰, load/cpu能从0.5瞬间飙升到5以上,每次持续15s-2mins. 波峰比较严重时候,会导致PHP进程数占满,进而影响API接口的新入请求.

由于每次发生的时间间隔大概2个小时, 但是没有规律. zabbix监控对这种突发最好只做到在1.5分钟后通知, 失去了事故现场.

由于报警延迟, 只能一边开着terminal实时观察, 一边在下次故障发生前排查其他的可能性.

怀疑是最近变更. 近期postgresql刚安装了jieba分词插件. 有可能会导致这个问题.

怀疑是由5%慢请求拖累整个数据库,造成服务器性能不够.这个根据经验是最可能的.

怀疑定时任务导致瞬时大量请求.

怀疑是因为数据量增大后内存热数据不够导致.

怀疑是vacuum或其他后台进程导致.

排查的过程中, 突然抓到事故现场. 立即查看内存和CPU相关指标.

1. _spin_unlock_irqrestore 占用89%的CPU时间.

2. 单个sql请求消耗内存大概是25M.

grep Pss /proc/`ps auxf | grep hbforce_v4| grep -ir select | tail -n 1  | awk '{print $2}'`/smaps |awk '{total+=$2}; END {print total}'

3. 内存现状,显示还有大量的cached内存, 系统故障时候伴随着内存也扫描和回收.(低于/proc/zoneinfo的low的值时触发回收,回收到high停止)

用到的知识点:

在系统空闲内存低于 watermark[low]时，开始启动内核线程kswapd进行内存回收.直到该zone的空闲内存数量达到watermark[high]后停止回收。如果上层申请内存的速度太快，导致空闲内存降至watermark[min]后，内核就会进行direct reclaim（直接回收），即直接在应用程序的进程上下文中进行回收，再用回收上来的空闲页满足内存申请，因此实际会阻塞应用程序.当前情况下.min-low-high之间只有15320KB的内存差.

而一个postgresql请求中需要分配的内存一般会在25MB左右.会导致直接触发强制回收.

下面是定位出来的触发逻辑:

1.内存不足时,单次申请内存过大,导致直接强制回收.触发compat_zone, 导致自旋锁,这个锁的特点是等待锁的过程中不休眠,而是占着CPU空转.spin_unlock_irqrestore — 禁止内核抢占并屏蔽中断，事先保存中断屏蔽位并事后恢复原状.

2.CPU空转导致新进入的任务堆积,load升高,并占用连接.

3.PHP不能处理导致进程占用,PHP-FPM进程达到最大值时候阻塞新请求进入.

4.API接口超时,导致前端调用失败,显示接口等待或失败.

5.内存回收完毕后释放锁,然后恢复正常.

总结原因是单次内存申请超过了min-low-high间隔,导致强制回收,触发了自旋锁.

调整内核参数解决:

vm.min_free_kbytes = 1081344

vm.vfs_cache_pressure = 200

当时的现场的数据:

[root@DATABASE ~]# cat /proc/zoneinfo

Node 0, zone   Normal

  pages free     20198

        min      15319

        low      19148

        high     22978

[root@DATABASE ~]# free -m

             total       used       free     shared    buffers     cached

Mem:         32109      31778        330          0        256      30215

-/+ buffers/cache:       1307      30802

Swap:        0        0      0

[root@DATABASE ~]# cat /proc/meminfo

MemTotal:       32879936 kB

MemFree:         2506208 kB

Buffers:          892660 kB

Cached:         28122840 kB

SwapCached:            0 kB

Active:         16954896 kB

Inactive:       12560144 kB

Active(anon):    3459900 kB

Inactive(anon):   310148 kB

Active(file):   13494996 kB

Inactive(file): 12249996 kB

Unevictable:           0 kB

Mlocked:               0 kB

SwapTotal:             0 kB

SwapFree:              0 kB

Dirty:              7004 kB

Writeback:             0 kB

AnonPages:        258360 kB

Mapped:          3255272 kB

Shmem:           3271380 kB

Slab:             471896 kB

SReclaimable:     419744 kB

SUnreclaim:        52152 kB

KernelStack:        3680 kB

PageTables:        38140 kB

NFS_Unstable:          0 kB

Bounce:                0 kB

WritebackTmp:          0 kB

CommitLimit:    16439968 kB

Committed_AS:    8292496 kB

VmallocTotal:   34359738367 kB

VmallocUsed:       65256 kB

VmallocChunk:   34359667396 kB

HardwareCorrupted:     0 kB

AnonHugePages:         0 kB

HugePages_Total:       0

HugePages_Free:        0

HugePages_Rsvd:        0

HugePages_Surp:        0

Hugepagesize:       2048 kB

DirectMap4k:        6016 kB

DirectMap2M:     2091008 kB

DirectMap1G:    31457280 kB

[root@DATABASE ~]# numactl --hardware

available: 1 nodes (0)

node 0 cpus: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15

node 0 size: 32767 MB

node 0 free: 1141 MB

node distances:

node   0

  0:  10

[root@DATABASE ~]# cat /proc/zoneinfo

Node 0, zone   Normal

  pages free     20198

        min      15319

        low      19148

        high     22978

        scanned  0

        spanned  7602176

        present  7498240

[root@DATABASE ~]# sar -B 1

Linux 2.6.32-279.el6.x86_64 (DATABASE) 06/21/2017 _x86_64_ (16 CPU)

12:51:57 AM  pgpgin/s pgpgout/s   fault/s  majflt/s  pgfree/s pgscank/s pgscand/s pgsteal/s    %vmeff

12:51:58 AM    129.17    612.50  13683.33      0.00  23310.42      0.00   7663.54   7704.17    100.53

12:51:59 AM   1872.34     12.77  17207.45      0.00  29784.04      0.00   2325.53   2325.53    100.00

12:52:00 AM    148.84      0.00  19734.30     11.05  24716.86      0.00   4424.42   4424.42    100.00

12:52:01 AM     84.21      0.00   2047.37     21.05  18484.21      0.00   4347.37   4178.95     96.13

12:52:02 AM   1025.00      0.00  18497.92      2.08  22652.08      0.00   5256.25   5289.58    100.63

12:52:03 AM   2235.79    450.53  52714.74      4.21  87222.11      0.00  24298.95  24297.89    100.00

12:52:05 AM     13.45      6.72  13763.87      0.00  22565.55      0.00   1813.45   1813.45    100.00

12:52:06 AM      8.00      0.00  14222.00      0.00  16852.00      0.00   5255.00   5199.00     98.93

12:52:07 AM  11734.69    114.29 190776.53      1.02 223285.71      0.00  43768.37  43814.29    100.10

12:52:08 AM  58848.98   1559.18 226263.27      0.00 233448.98      0.00   1057.14   1057.14    100.00

12:52:09 AM 108673.47     24.49 140714.29      0.00 142710.20      0.00      0.00      0.00      0.00

12:52:10 AM  65834.34     16.16  41429.29      0.00  42891.92      0.00      0.00      0.00      0.00

12:52:11 AM  59104.17      0.00  59959.38      0.00  60518.75      0.00      0.00      0.00      0.00

12:52:12 AM  56040.40    137.37  46878.79      0.00  40731.31      0.00      0.00      0.00      0.00

对应的是

procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu-----

82  1      0 581128 587036 30372132    0    0 17092   616 63036 2132  1 99  0  0  0

73  1      0 687572 586204 30274540    0    0  1476    24 18942  581  0 100  0  0  0

83  0      0 700872 585844 30250296    0    0   432   588 16374  427  0 100  0  0  0

51  1      0 715412 585816 30238628    0    0  1752    12 16660  508  1 99  0  0  0

87  1      0 726340 585784 30229336    0    0   212     0 17575  480  1 99  0  0  0

88  1      0 742876 585760 30196484    0    0   116     0 25373  712  1 99  0  0  0

80  1      0 753324 585620 30180436    0    0  1328   428 17074  504  1 99  0  0  0

90  0      0 828596 585088 30092832    0    0  1736     8 19115 1378  1 99  0  0  0

86  0      0 835460 585000 30088000    0    0    16     0 17247  461  0 100  0  0  0

82  0      0 888980 584364 29995256    0    0    24     8 18090  574  1 99  0  0  0

 1  1      0 1012756 583688 29915708    0    0 20796   112 19206 4382  6 73 20  1  0

 1  1      0 1018156 583952 29982312    0    0 68868  1520 8720 5912  4  7 85  3  0

 0  1      0 962080 584016 30083852    0    0 101396    24 6240 4274  3  4 89  4  0

 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st

 1  1      0 906804 584032 30144308    0    0 61180    16 4026 3513  1  2 93  4  0

这些信息没有在默认的监控中体现出来, 后续又细化zabbix内存监控.

细化的模板在这里

参考文章:

http://blog.2baxb.me/archives/1065

https://engineering.linkedin.com/performance/optimizing-linux-memory-management-low-latency-high-throughput-databases

https://www.kernel.org/doc/gorman/html/understand/understand013.html

http://os.51cto.com/art/201310/412638.htm

http://www.cs.fsu.edu/~baker/devices/lxr/source/2.6.11.8/linux/mm/mempool.c

http://blog.csdn.net/longxibendi/article/details/44625703

https://www.google.com/#newwindow=1&hl=en&q=kswapd+spin_unlock_irqrestore+cpu

https://www.google.com/#q=%22compact_zone%22+spin_unlock_irqrestore

业务请求稳步上升, PHP接口服务器资源又吃紧了, 在巡检时发现了一个有趣的现象引起了我的注意. 其中一台的CPU资源占用相对其他相同配置服务器小10-15%左右, 预计有比较可观的深挖价值.

(标题先卖个关子, 通过这个关子引出下面的3种解决问题的思路), 下面请看3种排查思路.

 

首先先看"错误"示范:

 

既然负载表现有差别, 第一思路就是该"大家来找茬"了, 在这个思路下分别排查了:

1.负载均衡分配规则.

2.负载均衡中配置权重相同, 业务请求量日志也大致相同.

3.服务器内核版本和参数.

4.PHP的编译参数, gcc版本.

5.PHP报错日志.

查看系统的message日志,其中中会有一些redis插件相关的段错误. 由于以前处理过redis插件的内存泄露问题,所以重新编译最新版本的redis.so库,检查没有了段错误.但是对性能并没有任何提升

6.服务器防火墙配置.

性能好的服务器防火墙取消了TCP请求跟踪,  其他服务器上也取消TCP请求跟踪后后性能差异也没有明显提高.

7.外部请求速度差异.

在链路监控日志中对比, 2台服务器请求数据库/缓存等接口速度无差异. 网络消耗也无差异.

8.系统内核调用差异.类调用差异.

通过strace追踪系统内核调用差异,和ltrace跟踪so文件时间调用差异. 内核调用差异.这种差距可以对比出,但是分析这种差异太过复杂,不直观.

走到这里, 这条思路基本上是走到死胡同了.虽然发现了一些可以优化的地方, 但是并没有找到差异真正原因. 所以需要转变思路, 通过判断推理而不是假设验证来定位.

 

下面请看"能解决问题"的示范:

 

1.进程分组汇总后,观察某类进程占用资源的对比.

watch -d -n 1 "ps aux | awk '{S[\$11]+=\$3} END { for (i in S) print  S[i], i}' | sort -nr"

发现确实根本原因还是在php-fpm的差异上,与其他的应用无关.

2.内核态CPU差距不大,用户态CPU有15%左右的差距.load值会有1-2倍的差异.这个比例就比较蹊跷了.通过vmstat -n 1发现,CPU等待队列数基本保持在3-5附近,偶尔会突然增高到20-30附近,并迅速下降,这种情况会导致CPU的用户态差距不大,而系统load差距非常大.平时正常,但是波峰过大.

3.这种情况需要查找CPU任务堆积的分配, 通过观察CPU时钟来推断产生问题的原因.

通过perf top对比发现.性能差的服务器中会有大量的mutex_spin_on_owner和_spin_unlock_irqrestore时间占用.

关于这个的解释:

It's bad reporting by perf, not cycles consumed by _spin_unlock_irqrestore.

When IRQs are disabled, perf's interrupts are not processed. Instead, they're processed when interrupts are re-enabled. When perf's interrupt handler looks at the instruction pointer, to see what code was running, it finds the function that enabled interrupts - quite often it's _spin_unlock_irqrestore.

So all you know is that the cycles were consumed by code that had interrupts disabled, and enabled them using _spin_unlock_irqrestore.

If you can get perf to use NMI (non maskable interrupt), it could solve this problem.

I know that it can be done with oprofile (perf's predecessor) by changing the makefile, but don't know about perf.

大意是:这个问题是在处理多核CPU均衡相关的内容,但这个问题只是表现症状,并不是根本原因.这个内容和CPU抢占,自旋锁等锁,和多核CPU均衡相关的内容.进一步分析发现这些内容是由php-fpm发起的.

对比性能较好的服务器:

 

性能差的API服务器中libgomp.so.1.0.0 gomp_barrier_wait_end的调用占据了大量的CPU时钟.

调查发现openmp是和多核CPU并行相关的.软件编译的过程中,可以利用这个动态库,达到充分利用多核CPU的目的. 关闭openmp的多核功能后, 性能得到提升, 问题得到解决.

以上是调查过程中的思路和方法, 问题虽然得到解决, 但是还是有一些推理盲点存在, 仍然有些运气成分, 不能让人完全信服.

 

下面请看"正确"的示范:

思路是通过查找出这个动态库的上游调用,来找到有问题的点.通过perf工具查出,这个库的最上游调用时php-fpm.(果然,最终还回到了php-fpm).具体是php-fpm的哪个步骤出了问题需要进一步推断.

1: 查找任意一个php-fpm的文件调用.

lsof -p `ps aux | grep "[p]hp-fpm: pool"| head -n 1 | awk '{print $2}'`

2: 查看php-fpm的动态库调用树.比较取巧的方式是从文件调用中查到so文件,只需要查下一级的ldd调用即可.

lsof -p `ps aux | grep "[p]hp-fpm: pool"| head -n 1 | awk '{print $2}'`

| awk '{print $NF}'| sort |uniq | grep so | xargs ldd

搜索这些调用树:

/usr/lib64/libMagickCore.so.5.0.0

/usr/lib64/libMagickWand.so.5.0.0

/usr/local/php7/lib/php/extensions/debug-non-zts-20151012/imagick.so

只有这几个so用到了那个libgomp.so.1

rpm -qf /usr/lib64/libMagickWand.so.5.0.0

ImageMagick-6.7.2.7-4.el6_7.x86_64

到此为止,真正的问题找到了.就是ImageMagick这个文件产生了CPU多核调用,从而导致的出现频繁的波峰.

然后调查这个软件和多核CPU相关的部分:

identify -list Configure

返回的结果中:

FEATURES      OpenMP

发现默认是启用了OpenMP.

性能好的服务器当时为了修复ImageMagick的一个软件安全隐患, 除了有yum安装的多核版本, 还有一个关闭掉多核功能的版本, 编译参数中有一项CONFIGURE      ./configure  '--disable-openmp'.关闭多核功能. imagic.so编译的时候使用了无多核版本的库文件.

所以,问题就非常明了了. 在有和图片处理相关的请求中,理论上这个请求能占用所有的CPU资源.这会导致后续的PHP请求堆积,有个比较大的高峰.

开启多核功能在有些场景下使用,但作为PHP的库时,并不一定是最佳实践.

 

解决方法:

1.重新编译其余服务器的ImageMagick软件,关闭多核心功能.并重新编译so解决.

2.在PHP调用的时候手动制定最多使用1颗CPU.但是这种方式需要修改的PHP文件调用可能比较多,所以并不采用.

最终结果:重新编译后,perf top观察没有多核CPU相关/锁相关CPU时钟占用.系统性能也区域稳定,理论上会多支持20%-30%左右的请求量..

关于这次调查中总结的非技术问题.下篇再接着总结吧.

--------------------

参考文章:

https://www.google.com/#q=linux++disable+OpenMP+

https://www.google.com/#q=gomp_barrier_wait_end

https://www.google.com/#q=gomp_barrier_wait_end+php

http://stackoverflow.com/questions/14703328/spin-unlock-irqrestore-has-very-high-sampling-rate-in-my-kvm-why

https://www.google.com/#q=spin_unlock_irqrestore+high

https://www.google.com/#q=php+7++imagemagick+libgomp

ImageMagick这个插件

http://stackoverflow.com/questions/14703328/spin-unlock-irqrestore-has-very-high-sampling-rate-in-my-kvm-why

http://stackoverflow.com/questions/7847900/disable-openmp-in-nice-way

http://stackoverflow.com/questions/1357604/turn-off-openmp

http://stackoverflow.com/questions/5697824/openmp-gcc-gomp-wasteful-barrier

http://stackoverflow.com/questions/39116329/enable-disable-openmp-locally-at-runtime/39119009

http://stackoverflow.com/questions/1357604/turn-off-openmp

http://boomshadow.net/tech/installs/installing-imagemagick-php-imagick/

http://www.daniloaz.com/en/high-cpu-load-when-converting-images-with-imagemagick/

分析PHP慢的原因有很多种:

比如通过xhprof.

有些通过sort/uniq的组合操作分析.

其实如果已经有了ELK(现在叫elastic stack)的话, 甚至可以更直观, 更方便前后对比.

今天来说一说如何通过分析php_slow_log快速"定位(估计)"慢的环节.

思路来源自这篇文章: http://chenlinux.com/2015/03/06/kibana4-for-slowlog/

效果图:

 

最外圈是调用栈最一层的比例, 第二层是调用栈第二层.

这种图可以在PHP变慢的时候可以快速查看是哪个调用栈的问题. 比如数据库调用变慢, 还是内部逻辑问题.

 

可惜参考文章不是通过logstash实现, 看了一下logstash, 没有比较简单的原生实现. 这又何妨, 世上无难事只怕有心人,  索性拆分方式直接改为写ruby代码:

配置文件如下: 有这样需求的同学, 拿走, 不谢.

filter {
  if [type] == "php_fpm_slow" {
    grok {
      match => {
        message => "(?m)\[(?<timestamp>\d{2}-\w{3}-\d{4} \d{2}:\d{2}:\d{2})\]\s+\[(?<pool_name>\w+\s\w+)\]\spid\s%{NUMBER:php_pid:int}\nscript_filename = %{UNIXPATH:slow_script}\n(?<php_slow_stack>\[\w{18}\] (?<slow_func>[^\[]*?:\d+).*\[\w{18}\](?<begin_func>[^\[]*?:\d+))$"
      }
    }
    mutate {
      gsub => ["php_slow_stack", "\[\w{18}\] ", ""]
    }
    ruby {
      code => "php_slow_stack_hash = Hash.new; if event.get('php_slow_stack'); event.get('php_slow_stack').split(/\r?\n/).each_with_index {|item, index| php_slow_stack_hash[index] = item }; end; event.set('php_slow_stack', php_slow_stack_hash)"
    }
    mutate {
        merge => ["php_slow_stack", "php_slow_stack"]
    }

  }
}

output {
  if [type] == "php_fpm_slow" {
    elasticsearch {
      hosts => ["10.24.252.67:9200"]
      index => "php-fpm-slow-log-%{+YYYY.MM.dd}"
      document_type => "%{type}"
      flush_size => 2000
      idle_flush_time => 5
    }
  }
}

问题终于解决了, 本来想总结一下, joshua已经总结完了, 还比我自己总结的更好.

索性偷个懒(偷懒也需要找理由啊)

链接: Elasticsearch 内存那点事

那我就说一下ELK中其他的性能提升方式吧.

如果要实现业务系统日志汇总分析, 直接推动业务系统直接输出json格式的日志吧.

如果输出了plain 格式, 还需要耗费CPU去分析正则, 性能耗费不是一般地说.

grek在线debug，需要翻墙

http://grokdebug.herokuapp.com/

grok的解析式

https://github.com/logstash-plugins/logstash-patterns-core/blob/master/patterns/grok-patterns