通过Strace定位故障原因

标签: Technical Strace | 发表时间:2013-10-06 01:07 | 作者:老王
出处:http://huoding.com

俗话说:不怕贼偷,就怕贼惦记着。在面对故障的时候,我也有类似的感觉:不怕出故障,就怕你不知道故障的原因,眼睁睁地看着情况恶化却束手无策。

十一长假还没结束,服务器却频现高负载,Nginx出现错误日志:

  • connect() failed (110: Connection timed out) while connecting to upstream
  • connect() failed (111: Connection refused) while connecting to upstream

看上去是Upstream出了问题,在本例中Upstream就是PHP。一开始我搞不清楚到底是哪个PHP脚本出现了问题,无奈之下只好通过不断重启PHP服务来缓解高负载故障。

如果每次都手动重启服务无疑是个苦差事,好在可以通过CRON设置每分钟执行:

#/bin/bash

LOAD=$(awk '{print $1}' /proc/loadavg)

if [ $(echo "$LOAD > 100" | bc) = 1 ]; then
    /etc/init.d/php-fpm restart
fi

可惜这只是一个权宜之计,要想彻底解决就必须找出故障的真正原因是什么。

好在有Strace,让我们通过它来统计一下各个系统调用的耗时情况:

shell> strace -c -p $(pgrep -n php-fpm)

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 30.53    0.023554         132       179           brk
 14.71    0.011350         140        81           mlock
 12.70    0.009798          15       658        16 recvfrom
  8.96    0.006910           7       927           read
  6.61    0.005097          43       119           accept
  5.57    0.004294           4       977           poll
  3.13    0.002415           7       359           write
  2.82    0.002177           7       311           sendto
  2.64    0.002033           2      1201         1 stat
  2.27    0.001750           1      2312           gettimeofday
  2.11    0.001626           1      1428           rt_sigaction
  1.55    0.001199           2       730           fstat
  1.29    0.000998          10       100       100 connect
  1.03    0.000792           4       178           shutdown
  1.00    0.000773           2       492           open
  0.93    0.000720           1       711           close
  0.49    0.000381           2       238           chdir
  0.35    0.000271           3        87           select
  0.29    0.000224           1       357           setitimer
  0.21    0.000159           2        81           munlock
  0.17    0.000133           2        88           getsockopt
  0.14    0.000110           1       149           lseek
  0.14    0.000106           1       121           mmap
  0.11    0.000086           1       121           munmap
  0.09    0.000072           0       238           rt_sigprocmask
  0.08    0.000063           4        17           lstat
  0.07    0.000054           0       313           uname
  0.00    0.000000           0        15         1 access
  0.00    0.000000           0       100           socket
  0.00    0.000000           0       101           setsockopt
  0.00    0.000000           0       277           fcntl
------ ----------- ----------- --------- --------- ----------------
100.00    0.077145                 13066       118 total

看上去「brk」非常可疑,它竟然耗费了三成的时间,保险起见,单独确认一下:

shell> strace -T -e brk -p $(pgrep -n php-fpm)

brk(0x1f18000) = 0x1f18000 <0.024025>
brk(0x1f58000) = 0x1f58000 <0.015503>
brk(0x1f98000) = 0x1f98000 <0.013037>
brk(0x1fd8000) = 0x1fd8000 <0.000056>
brk(0x2018000) = 0x2018000 <0.012635>

说明:在Strace中和操作花费时间相关的选项有两个,分别是「-r」和「-T」,它们的差别是「-r」表示相对时间,而「-T」表示绝对时间。简单统计可以用「-r」,但是需要注意的是在多进程背景下,CPU随时可能会被切换出去做别的事情,所以相对时间不一定准确,此时最好使用「-T」,在行尾可以看到操作时间,可以发现确实很慢。

在继续定位故障原因前,我们先通过「man brk」来查询一下它的含义:

brk() sets the end of the data segment to the value specified by end_data_segment, when that value is reasonable, the system does have enough memory and the process does not exceed its max data size (see setrlimit(2)).

简单点说就是内存不够用时通过它来申请新内存( data segment),可是为什么呢?

shell> strace -T -p $(pgrep -n php-fpm) 2>&1 | grep -B 10 brk

stat("/path/to/script.php", {...}) = 0 <0.000064>
brk(0x1d9a000) = 0x1d9a000 <0.000067>
brk(0x1dda000) = 0x1dda000 <0.001134>
brk(0x1e1a000) = 0x1e1a000 <0.000065>
brk(0x1e5a000) = 0x1e5a000 <0.012396>
brk(0x1e9a000) = 0x1e9a000 <0.000092>

通过「grep」我们很方便就能获取相关的上下文,可以发现每当请求某些PHP脚本时,就会出现若干条耗时的「brk」,而且这些PHP脚本有一个共同的特点,就是非常大,甚至有几百K,为何会出现这么大的PHP脚本?原来是程序员为了避免数据库操作,把非常庞大的数组变量通过「 var_export」持久化到PHP文件中,然后在程序中通过「 include」来获取相应的数据,由于「brk」操作比较慢,导致PHP处理请求的时间过大,加之PHP进程数有限,从而在Nginx上会出现请求拥堵现象,最终导致高负载故障。

拥抱故障,每一个故障都是学习的好机会,希望本文能给你些许启发。

相关 [strace 原因] 推荐:

通过Strace定位故障原因

- - 火丁笔记
俗话说:不怕贼偷,就怕贼惦记着. 在面对故障的时候,我也有类似的感觉:不怕出故障,就怕你不知道故障的原因,眼睁睁地看着情况恶化却束手无策. 十一长假还没结束,服务器却频现高负载,Nginx出现错误日志:. 看上去是Upstream出了问题,在本例中Upstream就是PHP. 一开始我搞不清楚到底是哪个PHP脚本出现了问题,无奈之下只好通过不断重启PHP服务来缓解高负载故障.

strace命令小结

- - jackyrong
strace命令是很有用的进程跟踪命令,下面小结下:. 1 strace 是一个非常简单的工具,用来跟踪可执行程序的系统调用(system call). 最简单的使用是,它追踪可行程序运行时的整个生命周期,输出每一个系统调用的名字,参数和返回值. 但是它还可以做更多的事情:. 它可以基于系统调用或者系统调用组来过滤.

[译]strace的10个命令

- - 鸟窝
strace是一个在类Unix操作系统如Linux上做debugging和trouble shooting的超级好用的工具. 它可以捕获和记录进程的所有系统调用,以及这个进程接收的所有信号. 原文: 10 Strace Commands for Troubleshooting and Debugging Linux Processes.

linux strace - 追踪系统调用

- - Linux - 操作系统 - ITeye博客
有时候发现有个别进程占用了大量CPU或者内存,我们可以查看进程的调用情况. 已有 0 人发表留言,猛击->> 这里<<-参与讨论. —软件人才免语言低担保 赴美带薪读研.

Linux 中用 strace 追踪系统调用和信号值

- - 博客园_iTech's Blog
原文地址: http://www.dbabeta.com/2009/strace.html. 打开man strace,我们能看到对strace的最简洁的介绍就是”strace – trace system calls and signals”. 实际上strace是一个集诊断、调试、统计与一体的工具,我们可以使用strace对应用的系统调用和信号传递的跟踪结果来对应用进行分析,以达到解决问题或者是了解应用工作过程的目的.

手把手教你用Strace诊断问题

- - 火丁笔记
早些年,如果你知道有个 strace 命令,就很牛了,而现在大家基本都知道 strace 了,如果你遇到性能问题求助别人,十有八九会建议你用 strace 挂上去看看,不过当你挂上去了,看着满屏翻滚的字符,却十有八九看不出个所以然. 本文通过一个简单的案例,向你展示一下在用 strace 诊断问题时的一些套路.

脱发的十大原因

- Marc - 译言-每日精品译文推荐
来源Top 10 Causes of Hair Loss. While it’s easy to blame your parents for your thin hair or balding scalp, not all causes of hair loss trace back to genetics.

Node.js 盛行的原因

- - ITeye资讯频道
在过去的18个月,Node.js的使用率呈指数级的增长,很多大型互联网企业也纷纷转向Node.js:. Groupon抛弃Rails,转向Node.js. 看eBay如何评价他们的Node.js首次尝鲜. LinkedIn缘何抛弃Ruby,转投NodeJS怀抱. JavaScript社区开发者调查:服务端JS盛行.

[转贴]温州高铁事故原因

- DayuLu - 牛博山寨 编辑推荐
让我吃惊的是,铁道部竟然在缺乏ATP技术的情况下,就强行开通了高铁. 现在铁道部应该做的就是,立即把所有高铁列车降到160公里时速运行. 现在中国高铁使用的所谓ATP装置其实是LKJ升级版,是很低级的ATP,只配使用在160公里以下时速的普通列车上. 现在世界上比较先进的ATP车载设备,工作原理是向轨道发射信号,跟在后面的列车接收信号并经过计算得出与前车距离.

Google Wave失败的原因与教训

- cgeek - 可能吧
Google昨天宣布将停止开发Google Wave,因为它的用户数量达不到Google的预期,但会维持它的运行并将部分代码开源. 在写前面一句话的时候,我在思考要不要先介绍一下"Google Wave"是什么,但我陷入了困境,因为我不能用简短的语句来描述Google Wave是什么. 我去年很早就拿到了Google Wave的内测资格,但基本上很少用,我觉得它不是不能替代的,它能完成的工作,有其它服务比它做得更好.