(转)Linux利器 strace
GodLong 2011-08-27
原文：http://www.perfgeeks.com/?p=501
今天才发现strace是个好东西呀
strace常用来跟踪进程执行时的系统调用和所接收的信号。在Linux世界，进程不能直接访问硬件设备，当进程需要访问硬件设备(比如读取磁盘文件，接收网络数据等等)时，必须由用户态模式切换至内核态模式，通过系统调用访问硬件设备。strace可以跟踪到一个进程产生的系统调用,包括参数，返回值，执行消耗的时间。
strace使用参数
-p跟踪指定的进程
-f跟踪由fork子进程系统调用
-F尝试跟踪vfork子进程系统调吸入，与-f同时出现时,vfork不被跟踪
-ofilename默认strace将结果输出到stdout。通过-o可以将输出写入到filename文件中
-ff常与-o选项一起使用，不同进程(子进程)产生的系统调用输出到filename.PID文件
-r打印每一个系统调用的相对时间
-t在输出中的每一行前加上时间信息。-tt时间确定到微秒级。还可以使用-ttt打印相对时间
-v输出所有系统调用。默认情况下，一些频繁调用的系统调用不会输出
-s指定每一行输出字符串的长度,默认是32。文件名一直全部输出
-c统计每种系统调用所执行的时间，调用次数，出错次数。
-eexpr输出过滤器，通过表达式，可以过滤出掉你不想要输出
应用场景
#1.跟踪你的web服务器系统调用
系统调用优化，也是web性能优化的一个较为重要的方向，尤其是在I/O密集型web应用的情况。我们这里的测试环境是CentOS5.4+Nginx+FastCGI。
<?php
//file:hello.php
define('DOCUMENT_ROOT',dirname(__FILE__));
include("hello.inc");
include("./hello.inc");
include(DOCUMENT_ROOT."/hello.inc");
?>
#strace-f-F-ostrace_nginxstrace/wwwchroot/nginx/sbin/nginx-c/wwwchroot/nginx/nginx.conf
...(有部分不重要的数据影响排版，在这里使用...代替)
//--接受来自客户端的http请求
4165recv(16,"GET/hello.phpHTTP/1.1\r\nHost:f"...,32768,0)=391
4165epoll_ctl(9,EPOLL_CTL_MOD,16,{EPOLLIN|EPOLLOUT|EPOLLET,{u32=3081162952,u64=698098541354471624}})=0
//--进行DNS查找
4165getsockname(16,{sa_family=AF_INET,sin_port=htons(80),sin_addr=inet_addr("222.73.211.214")},[16])=0
//--新建一个socket，连接Fast-CGI,端口号为9000
4165socket(PF_INET,SOCK_STREAM,IPPROTO_IP)=17
4165ioctl(17,FIONBIO,[1])=0
4165epoll_ctl(9,EPOLL_CTL_ADD,17,{EPOLLIN|EPOLLOUT|EPOLLET,{u32=3081163048,u64=697886249710965032}})=0
4165connect(17,{sa_family=AF_INET,sin_port=htons(9000),sin_addr=inet_addr("127.0.0.1")},16)=-1)
4165epoll_wait(9,{{EPOLLOUT,{u32=3081163048,u64=697886249710965032}},{...},5\
12,300000)=2
4165gettimeofday({1295420285,130967},NULL)=0
4165recv(16,0xbfdd7d8b,1,MSG_PEEK)=-1EAGAIN(Resourcetemporarilyunavailable)
4165getsockopt(17,SOL_SOCKET,SO_ERROR,[0],[4])=0
//--将用户http请求交给Fast-CGI
4165writev(17,[{"\1\1\0\1\0\10\0\0\0\1\0\0\0\0\0\0\1\4\0\1\3\30\0\0\21\7GATEWA"...,832}],1)=832
4165epoll_wait(9,{{EPOLLIN|EPOLLOUT,{u32=3081163048,u64=697886249710965032}}},512,300000)=1
4165gettimeofday({1295420285,131559},NULL)=0
//--接收Fast-CGI响应
4165recv(17,"\1\6\0\1\0V\2\0X-Powered-By:PHP/5.2.10"...,65536,0)=112
4165readv(17,[{"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,65424}],1)=0
4165mmap2(NULL,274432,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANONYMOUS,-1,0)=0xb7514000
4165close(17)=0
4165munmap(0xb7514000,274432)=0
//--响应客户端http请求,即http响应
4165writev(16,[{"HTTP/1.1200OK\r\nServer:nginx/0"...,228},{"22\r\n",4},...,5)=273
4165write(5,"116.66.34.82--[19/Jan/2011:14"...,191)=191
4165setsockopt(16,SOL_TCP,TCP_NODELAY,[1],4)=0
4165recv(16,0x9b024e8,32768,0)=-1EAGAIN(Resourcetemporarilyunavailable)
...
通过这些,我们只能够大概地了解，Nginx这里启用了epoll。同时，还可以了解到Nginx和Fast-CGI底层是如何运作的。奇怪，hello.php文件中有三个inclue，即加载了三次文件，这里没有看到相应的i/o逻辑操作，是为什么呢？这是因为，Nginx并没解析处理PHP脚本，而是交给Fast-CGI去做这部事情了。
#strace-f-F-ophp-cgi-strace/wwwchroot/php/bin/php-cgi--fpm-config/wwwchroot/php/etc/php-fpm.conf
//--接收来自Nginx发出的请求
4510<...acceptresumed>{sa_family=AF_INET,sin_port=htons(35983),sin_addr=inet_addr("127.0.0.1")},[16])=3
4510clock_gettime(CLOCK_MONOTONIC,{22638545,869965681})=0
4510poll([{fd=3,events=POLLIN}],1,5000)=1([{fd=3,revents=POLLIN}])
4510read(3,"\1\1\0\1\0\10\0\0",=8
4510read(3,"\0\1\0\0\0\0\0\0",=8
4510read(3,"\1\4\0\1\0035\3\0",=8
4510read(3,"\21\7GATEWAY_INTERFACECGI/1.1\17\5SERV"...,824)=824
4510read(3,"\1\4\0\1\0\0\0\0",=8
4510time(NULL)=1295425149
//--加载请求资源文件hello.php
4510lstat64("/var",{st_mode=S_IFDIR|0755,st_size=4096,...})=0
4510lstat64("/var/www",{st_mode=S_IFDIR|0755,st_size=4096,...})=0
4510lstat64("/var/www/ep",{st_mode=S_IFDIR|0755,st_size=4096,...})=0
4510lstat64("/var/www/ep/hello.php",{st_mode=S_IFREG|0644,st_size=119,...})=0
4510clock_gettime(CLOCK_MONOTONIC,{22638545,870893872})=0
4510setitimer(ITIMER_PROF,{it_interval={0,0},it_value={60,0}},NULL)=0
4510rt_sigaction(SIGPROF,{0x835c120,[PROF],SA_RESTART},{SIG_DFL,[],0},=0
4510rt_sigprocmask(SIG_UNBLOCK,[PROF],NULL,=0
4510time(NULL)=1295425149
4510open("/var/www/ep/hello.php",O_RDONLY)=4
4510fstat64(4,{st_mode=S_IFREG|0644,st_size=119,...})=0
4510time(NULL)=1295425149
4510chdir("/var/www/ep")=0
4510fstat64(4,{st_mode=S_IFREG|0644,st_size=119,...})=0
4510mmap2(NULL,4096,PROT_READ|PROT_WRITE,MAP_PRIVATE|MAP_ANONYMOUS,-1,0)=0xb7fe7000
4510read(4,"\n",8192)=29
4510read(4,"",8192)=0
4510read(4,"",8192)=0
4510close(4)=0
//--加载hello.inc,对应php代码include'./hello.inc'
4510getcwd("/var/www/ep"...,4096)=12
4510time(NULL)=1295425149
4510open("/var/www/ep/hello.inc",O_RDONLY)=4
4510fstat64(4,{st_mode=S_IFREG|0644,st_size=29,...})=0
4510read(4,"\n",8192)=29
4510read(4,"",8192)=0
4510read(4,"",8192)=0
4510close(4)=0
4510time(NULL)=1295425149
//--加载hello.inc,对应php代码includeDOCUMENT_ROOT.'/hello.inc'
4510lstat64("/var",{st_mode=S_IFDIR|0755,st_size=4096,...})=0
4510lstat64("/var/www",{st_mode=S_IFDIR|0755,st_size=4096,...})=0
4510lstat64("/var/www/ep",{st_mode=S_IFDIR|0755,st_size=4096,...})=0
4510lstat64("/var/www/ep/hello.inc",{st_mode=S_IFREG|0644,st_size=29,...})=0
4510open("/var/www/ep/hello.inc",O_RDONLY)=4
4510fstat64(4,{st_mode=S_IFREG|0644,st_size=29,...})=0
4510read(4,"\n",8192)=29
4510read(4,"",8192)=0
4510read(4,"",8192)=0
4510close(4)=0
//--将响结果输出给Nginx，并且关闭连接
4510write(3,"\1\6\0\1\0V\2\0X-Powered-By:PHP/5.2.10"...,96)=96
4510setitimer(ITIMER_PROF,{it_interval={0,0},it_value={0,0}},NULL)=0
4510write(3,"\1\3\0\1\0\10\0\0\0\0\0\0\0ere",16)=16
4510shutdown(3,1/*send*/)=0
4510recv(3,"\1\5\0\1\0\0\0\0",8,0)=8
4510recv(3,"",8,0)=0
4510close(3)=0
通过跟踪php-cgi，我们可以知道，相较与其它二种方法include‘./hello.inc’的性能是最高的。这里看到strace输出都被截断了，如果你需要看到更多的输出，可以通过-s选项，让strace输出更多内容。
当你发现某个http请求造成CPU占用效骤然升高，你可以通过strace跟踪查找问题的根源。同时，你也可以通过strace-c统计监控你的优化是否生效
#2.MySQL执行语句列表
当发生个http请求的时候，很多时候希望得到这个http请求发生了多少次数据库SELECT操作，是否在同一个mysqlconnection连接里面完成。这里以访问本页为例子，通过strace来跟踪这些MySQLSELECT查询语句。
//-9514是mysqld的进程号,为了看到整条SQL语句,我们通过-s1024希望输出更多内容
#strace-f-F-ff-ostrace-mysqld-s1024-p9514
#find.-name"strace-mysqld*"-typef-print|xargsgrep-n"SELECT.*FROMwp_"
./strace-mysqld.19203:64:
read(19,"\3SELECToption_name,option_valueFROMwp_optionsWHEREautoload='yes'",72)=72
./strace-mysqld.19203:165:
read(19,"\3SELECT*FROMwp_usersWHEREuser_login='admin'",50)=50
./strace-mysqld.19203:184:
read(19,"\3SELECTmeta_key,meta_valueFROMwp_usermetaWHEREuser_id=1",63)=63
./strace-mysqld.19203:295:
read(19,"\3SELECToption_valueFROMwp_optionsWHEREoption_name='rewrite_rules'LIMIT1",80)=80
./strace-mysqld.19203:311:
read(19,"\3SELECTwp_posts.*FROMwp_postsWHERE1=1ANDwp_posts.ID=501
ANDwp_posts.post_type='post'ORDERBYwp_posts.post_dateDESC",136)=136
...(这里省去了一些)
