使用strace跟踪多进程程序

1. 简介

strace可以跟踪到一个进程产生的系统调用,包括参数，返回值，执行消耗的时间。

2. 常用参数

• -p 跟踪指定的进程
• -o filename 默认strace将结果输出到stdout。通过-o可以将输出写入到filename文件中
• -ff 常与-o选项一起使用，不同进程(子进程)产生的系统调用输出到filename.PID文件
• -r 打印每一个系统调用的相对时间
• -t 在输出中的每一行前加上时间信息。
• -tt 时间确定到微秒级。还可以使用-ttt打印相对时间
• -s 指定每一行输出字符串的长度,默认是32。
• -c 统计每种系统调用所执行的时间，调用次数，出错次数。
• -e expr 输出过滤器，通过表达式，可以过滤出掉你不想要输出

3. 跟踪多进程的实例

要跟踪的Taskdemo.php代码如下（即之前使用swoole实现的生产者消费者模型）。

<?php
require("./Schedule.php");
class Taskdemo extends Schedule{
    protected $_consumerNum = 1;
    protected function doProduce($worker){
        $all = 5;
        for($i=0; $i<$all; $i+=1){
            yield json_encode(array("data"=>$i));
        }
    }

    protected function doConsume($data, $worker){
        sleep(1);
        echo "consumer:{$worker->pid} recv {$data}
";
    }
}

$t = new Taskdemo();
$t->run();

• Schedule.php详见这里
• 为方便讲述，将消费者的个数设为1。

执行如下命令，开始跟踪

strace -ff -o task php Taskdemo.php

执行后我们得到三个文件

task.28203  task.28204  task.28205

熟悉代码的同学应该可以猜到，这三个文件分别对应主进程，生产者子进程和消费者子进程。下面我们分别来看下。
- task.28203（主进程，通常来说进程号最小的文件就是主进程对应的文件）

/*生成生产者和消费者进程各一个*/
clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x2b6ea214c810) = 28204
clone(child_stack=0, clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x2b6ea214c810) = 28205

write(1, "msgqkey:1053566
", 16) = 16

/*等待并回收子进程*/
epoll_wait(7, 3841680, 4096, 4294967295) = -1 EINTR (Interrupted system call)
wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WNOHANG, NULL) = 28204
write(1, "master clear pid:28204, code:0
", 31) = 31
epoll_wait(7, 3841680, 4096, 4294967295) = -1 EINTR (Interrupted system call)
wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], WNOHANG, NULL) = 28205
write(1, "master clear pid:28205, code:0
", 31) = 31

• task.28204 消费者进程

/*从消息队列中取数据，输出*/
msgrcv(7176192, 7176192{2, "{"data":0}R7247r8HJ325r8"...}, 8192, 0, 0) = 10
write(1, "consumer:28204 recv {"data":0}
", 31) = 31
msgrcv(7176192, 7176192{2, "{"data":1}R7247r8HJ325r8"...}, 8192, 0, 0) = 10
write(1, "consumer:28204 recv {"data":1}
", 31) = 31
msgrcv(7176192, 7176192{2, "{"data":2}R7247r8HJ325r8"...}, 8192, 0, 0) = 10
write(1, "consumer:28204 recv {"data":2}
", 31) = 31
msgrcv(7176192, 7176192{2, "{"data":3}R7247r8HJ325r8"...}, 8192, 0, 0) = 10
write(1, "consumer:28204 recv {"data":3}
", 31) = 31
msgrcv(7176192, 7176192{2, "{"data":4}R7247r8HJ325r8"...}, 8192, 0, 0) = 10
write(1, "consumer:28204 recv {"data":4}
", 31) = 31
msgrcv(7176192, 7176192{1, "ALLDONE:4}R7247r8HJ325r8"...}, 8192, 0, 0) = 7
write(1, "consumer 28204 exit
", 20) = 20

• task.28205 生产者进程

write(1, "producer begin:
", 16) = 16
/*向队列中放入任务*/
msgsnd(7176192, {2, "{"data":0}"}, 10, 0) = 0
msgsnd(7176192, {2, "{"data":1}"}, 10, 0) = 0
msgsnd(7176192, {2, "{"data":2}"}, 10, 0) = 0
msgsnd(7176192, {2, "{"data":3}"}, 10, 0) = 0
msgsnd(7176192, {2, "{"data":4}"}, 10, 0) = 0
/*放入完成标识*/
msgsnd(7176192, {1, "ALLDONE"}, 7, 0) = 0
/*标签队列长度*/
msgctl(7176192, IPC_STAT, 0x7fffd6dbedb0) = 0
/*删除队列*/
msgctl(7176192, IPC_RMID, 0) = 0

4. 另一个十分有用的功能参数-c

统计每种系统调用所执行的时间，调用次数，出错次数。

strace -c php Taskdemo.php

我们执行上面的命令，看下主进程进行的系统调用。

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 59.06    0.000857         429         2           clone
 10.34    0.000150           1       153           mmap
  6.20    0.000090           1       109        42 open
  3.72    0.000054           1        78           fstat
  3.72    0.000054           1        62           mprotect
  3.58    0.000052           2        33        27 stat
  3.51    0.000051           1        74           close
  3.45    0.000050           1        66           read
  2.14    0.000031           1        26           brk
  1.79    0.000026           7         4         1 wait4
  ... ...
  0.00    0.000000           0         1           epoll_create
  0.00    0.000000           0         2         2 epoll_wait
------ ----------- ----------- --------- --------- ----------------
100.00    0.001451                   754        82 total

各项含义如下：
- % time：执行耗时占总时间百分比
- seconds：执行总时间
- usecs/call：单个命令执行时间
- calls：调用次数
- errors: 出错次数
- syscall: 系统调用

说明：
- clone是主进程生成子进程时的系统调用。
- epoll_create， epoll_wait，wait4用于创建信号处理函数，回收僵尸子进程。