straceを使った際の不具合調査

処理に時間がかかることがあり、どこが原因で遅くなっているのかを調べるときにstraceを利用して原因調査をしたことがあったので、使い方をまとめる。

基本的な使い方

  • これから処理を実行するとき

    • usage: strace 実行処理
    • ex: strace perl hoge.pl

  • 既に起動しているプロセスに対して実行するとき

    • usage: strace -p [pid]
    • ex: strace -p 111

よく使うオプション

オプション 説明
-p 指定したプロセスにアタッチし、トレースする。
-f 子プロセスについてもアタッチし、トレースする。
-T システムコールに費やした時間を表示する。
-tt それぞれの処理をマイクロ秒まで表示する。

使用例

  • ex1.)

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    20
    # /usr/bin/strace -fT -p 690
    Process 690 attached with 3 threads
    [pid   726] restart_syscall(<... resuming interrupted call ...> <unfinished ...>
    [pid   722] restart_syscall(<... resuming interrupted call ...> <unfinished ...>
    [pid   690] restart_syscall(<... resuming interrupted call ...>) = 1 <0.027705>
    [pid   690] read(3, 0x7ffcbe128ee0, 16) = -1 EAGAIN (Resource temporarily unavailable) <0.000050>
    [pid   690] clock_gettime(CLOCK_MONOTONIC, {1803655, 236362843}) = 0 <0.000042>
    [pid   690] write(3, "\1\0\0\0\0\0\0\0", 8) = 8 <0.000042>
    [pid   690] recvmsg(9, {msg_name(12)={sa_family=AF_NETLINK, pid=0, groups=00000400}, msg_iov(1)=[{"l\0\0\0\30\0\0\0\0\0\0\0\0\0\0\0\n\200\0\0\377\0\0\1\0\2\0\0\10\0\17\0"..., 16384}], msg_controllen=32, {cmsg_len=28, cmsg_level=SOL_SOCKET, cmsg_type=SCM_CREDENTIALS{pid=0, uid=0, gid=0}}, msg_flags=0}, 0) = 108 <0.000047>
    [pid   690] write(3, "\1\0\0\0\0\0\0\0", 8) = 8 <0.000041>
    [pid   690] clock_gettime(CLOCK_MONOTONIC, {1803655, 237019821}) = 0 <0.000057>
    [pid   690] poll([{fd=3, events=POLLIN}, {fd=10, events=POLLIN}, {fd=13, events=POLLIN}, {fd=16, events=POLLIN}, {fd=6, events=POLLIN}, {fd=7, events=POLLIN}, {fd=15, events=POLLIN}, {fd=9, events=POLLIN|POLLPRI}], 8, 247763) = 1 ([{fd=3, revents=POLLIN}]) <0.000039>
    [pid   690] clock_gettime(CLOCK_MONOTONIC, {1803655, 237225285}) = 0 <0.000021>
    [pid   690] clock_gettime(CLOCK_MONOTONIC, {1803655, 237285903}) = 0 <0.000021>
    [pid   690] poll([{fd=3, events=POLLIN}, {fd=10, events=POLLIN}, {fd=13, events=POLLIN}, {fd=16, events=POLLIN}, {fd=6, events=POLLIN}, {fd=7, events=POLLIN}, {fd=15, events=POLLIN}, {fd=9, events=POLLIN|POLLPRI}], 8, 247763) = 1 ([{fd=3, revents=POLLIN}]) <0.000035>
    [pid   690] read(3, "\2\0\0\0\0\0\0\0", 16) = 8 <0.000022>
    [pid   690] clock_gettime(CLOCK_MONOTONIC, {1803655, 237501095}) = 0 <0.000021>
    [pid   690] clock_gettime(CLOCK_MONOTONIC, {1803655, 237560551}) = 0 <0.000022>
    [pid   690] poll([{fd=3, events=POLLIN}, {fd=10, events=POLLIN}, {fd=13, events=POLLIN}, {fd=16, events=POLLIN}, {fd=6, events=POLLIN}, {fd=7, events=POLLIN}, {fd=15, events=POLLIN}, {fd=9, events=POLLIN|POLLPRI}], 8, 247763^CProcess 690 detached
     <detached ...>

  • ex2.)

    1
    2
    3
    4
    5
    # /usr/bin/strace -f -p 690 -tt
    Process 690 attached with 3 threads
    [pid   726] 21:48:39.863387 restart_syscall(<... resuming interrupted call ...> <unfinished ...>
    [pid   722] 21:48:39.863464 restart_syscall(<... resuming interrupted call ...> <unfinished ...>
    [pid   690] 21:48:39.863478 restart_syscall(<... resuming interrupted call ...>

参考URL