strace の -k オプションでスタックトレースを出す

strace で -k を指定すると システムコール呼び出しのスタックトレースを採取できるのを知った。v4.9 から使える experimental 扱いのオプション

       -k          Print  the execution stack trace of the traced processes after each system call (experimental).  This option is available only if strace is built with libunwind.
               

以下のような出力を得られる

$ strace -k ls
execve("/usr/local/bin/ls", ["ls"], 0x7ffcf3bcdd58 /* 26 vars */) = 0
 > /usr/lib64/libc-2.17.so(execve+0x7) [0xbf557]
 > /usr/local/bin/strace(exec_or_die+0x127) [0x2bd7]
 > /usr/local/bin/strace(startup_child+0x3c6) [0x24df6]
 > /usr/local/bin/strace(init+0x6c0) [0x25540]
 > /usr/local/bin/strace(main+0x16) [0x2c26]
 > /usr/lib64/libc-2.17.so(__libc_start_main+0xf5) [0x21c05]
 > /usr/local/bin/strace(_start+0x29) [0x379a]
brk(NULL)                               = 0x1281000
 > /usr/lib64/ld-2.17.so(__brk+0xc) [0x1826c]
 > /usr/lib64/ld-2.17.so(_dl_sysdep_start+0x148) [0x17448]
 > /usr/lib64/ld-2.17.so(_dl_start+0x381) [0x1bc1]
 > /usr/lib64/ld-2.17.so(check_one_fd.part.0+0x7d) [0x1178]
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f93c8f7a000
 > /usr/lib64/ld-2.17.so(__mmap+0x3a) [0x18f5a]
 > /usr/lib64/ld-2.17.so(__libc_memalign+0x84) [0x17db4]
 > /usr/lib64/ld-2.17.so(_dl_init_paths+0x91) [0x7ea1]
 > /usr/lib64/ld-2.17.so(dl_main+0x154b) [0x342b]
 > /usr/lib64/ld-2.17.so(_dl_sysdep_start+0x238) [0x17538]
 > /usr/lib64/ld-2.17.so(_dl_start+0x381) [0x1bc1]
 > /usr/lib64/ld-2.17.so(check_one_fd.part.0+0x7d) [0x1178]
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
 > /usr/lib64/ld-2.17.so(access+0x7) [0x18e57]
 > /usr/lib64/ld-2.17.so(dl_main+0x1700) [0x35e0]
 > /usr/lib64/ld-2.17.so(_dl_sysdep_start+0x238) [0x17538]
 > /usr/lib64/ld-2.17.so(_dl_start+0x381) [0x1bc1]
 > /usr/lib64/ld-2.17.so(check_one_fd.part.0+0x7d) [0x1178]

...

やったー

CentOS7

CentOS7.4 の strace-4.12-4.el7 ではサポートされていない機能だ。ざんねーん

$ rpm -qf /usr/bin/strace 
strace-4.12-4.el7.x86_64

$ /usr/bin/strace -k ps
/usr/bin/strace: invalid option -- 'k'
Try '/usr/bin/strace -h' for more information.

ちなみに Ubuntu Xenial もだめだー。とほほー

ビルドする

strace を git clone してきて、libunwind, libunwind-devel をインストールしておけば ./configure が勝手に検知して有効にしてくれた

ユースケース

障害や不具合の調査では、strace でシステムコールを読んで原因を絞り込んでいくことがある。そして問題のあるシステムコールを見つけることができたとしても、アプリケーションのどのコードから呼び出されいるかを突き止めるので手間がかかったりする

一つの方法として、GDBシステムコールに breakpoint を仕掛けてバックトレースをとると解決できるが、production で使うには GDB で停止するオーバーヘッドが問題になりそうだったり (注: 計測してみたら問題ないかも。感覚の話ですいません 😳 ) 、複数のシステムコールをまとめて追いかけたい際には不便 ... という問題を解決してくれそうなオプション

システムコールから逆引きで呼び出し元のシンボルとファイル名が一覧できるので、ただ単にソースコードリーディング用のツールとしても有用そう

実行例

ps コマンドの write(2) だけに絞り込んでスタックトレースを出す

$ strace -ewrite -k ps --quick-pid 1 
write(1, "  PID TTY          TIME CMD\n", 28  PID TTY          TIME CMD
) = 28
 > /usr/lib64/libc-2.17.so(__write_nocancel+0x7) [0xe9840]
 > /usr/lib64/libc-2.17.so(_IO_file_write+0x43) [0x75fb3]
 > /usr/lib64/libc-2.17.so(_IO_do_write+0x7c) [0x7741c]
 > /usr/lib64/libc-2.17.so(_IO_file_xsputn+0xb1) [0x76651]
 > /usr/lib64/libc-2.17.so(fwrite+0xed) [0x6c03d]
 > /usr/local/bin/ps(show_one_proc+0x3d6) [0x7146]
 > /usr/local/bin/ps(main+0x8ab) [0x2b2b]
 > /usr/lib64/libc-2.17.so(__libc_start_main+0xf5) [0x21c05]
 > /usr/local/bin/ps(_start+0x29) [0x2ca5]
write(1, "    1 ?        00:00:19 systemd\n", 32    1 ?        00:00:19 systemd
) = 32
 > /usr/lib64/libc-2.17.so(__write_nocancel+0x7) [0xe9840]
 > /usr/lib64/libc-2.17.so(_IO_file_write+0x43) [0x75fb3]
 > /usr/lib64/libc-2.17.so(_IO_do_write+0x7c) [0x7741c]
 > /usr/lib64/libc-2.17.so(_IO_file_xsputn+0xb1) [0x76651]
 > /usr/lib64/libc-2.17.so(fwrite+0xed) [0x6c03d]
 > /usr/local/bin/ps(main+0x8ab) [0x2b2b]
 > /usr/lib64/libc-2.17.so(__libc_start_main+0xf5) [0x21c05]
 > /usr/local/bin/ps(_start+0x29) [0x2ca5]
+++ exited with 0 +++

よいかんじだ

その他の使用例

例えば -P を組み合わせるて 特定のファイルを扱うシステムコールとトレースを観察する

id コマンドと /etc/passwd をトレースすると、libc の getpwuid(3) 呼び出しと中間に libnss_files が入っているのが分かる。ライブラリ関数や .so ライブラリの関係を把握できる。

$ strace -k -P /etc/passwd -y id
open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 3</etc/passwd>
 > /usr/lib64/libc-2.17.so(__open_nocancel+0x7) [0xe95a0]
 > /usr/lib64/libc-2.17.so(_IO_file_fopen+0x4c4) [0x77314]
 > /usr/lib64/libc-2.17.so(__fopen_internal+0x74) [0x6b5e4]
 > /usr/lib64/libnss_files-2.17.so(_nss_files_getpwuid_r+0x113) [0x60a3]
 > /usr/lib64/libc-2.17.so(getpwuid_r+0x15e) [0xbe52e]
 > /usr/lib64/libc-2.17.so(getpwuid+0x76) [0xbdc66]
 > /usr/local/bin/id(main+0x677) [0x20e7]
 > /usr/lib64/libc-2.17.so(__libc_start_main+0xf5) [0x21c05]
 > /usr/local/bin/id(_start+0x29) [0x2478]
fstat(3</etc/passwd>, {st_mode=S_IFREG|0644, st_size=1564, ...}) = 0
 > /usr/lib64/libc-2.17.so(__fxstat64+0x14) [0xe9154]
 > /usr/lib64/libc-2.17.so(_IO_file_doallocate+0x25) [0x6a9d5]
 > /usr/lib64/libc-2.17.so(_IO_doallocbuf+0x35) [0x784e5]
 > /usr/lib64/libc-2.17.so(_IO_file_underflow+0x1a4) [0x77654]
 > /usr/lib64/libc-2.17.so(_IO_default_uflow+0xe) [0x7856e]
 > /usr/lib64/libc-2.17.so(_IO_getline_info+0xa4) [0x6c514]
 > /usr/lib64/libc-2.17.so(fgets_unlocked+0x3d) [0x7569d]
 > /usr/lib64/libnss_files-2.17.so(internal_getent+0x8f) [0x5b0f]
 > /usr/lib64/libnss_files-2.17.so(_nss_files_getpwuid_r+0x81) [0x6011]
 > /usr/lib64/libc-2.17.so(getpwuid_r+0x15e) [0xbe52e]
 > /usr/lib64/libc-2.17.so(getpwuid+0x76) [0xbdc66]
 > /usr/local/bin/id(main+0x677) [0x20e7]
 > /usr/lib64/libc-2.17.so(__libc_start_main+0xf5) [0x21c05]
 > /usr/local/bin/id(_start+0x29) [0x2478]
read(3</etc/passwd>, "root:x:0:0:root:/root:/bin/bash\n"..., 4096) = 1564
 > /usr/lib64/libc-2.17.so(__read_nocancel+0x7) [0xe97e0]
 > /usr/lib64/libc-2.17.so(_IO_file_read+0x17) [0x76597]
 > /usr/lib64/libc-2.17.so(_IO_file_underflow+0x130) [0x775e0]
 > /usr/lib64/libc-2.17.so(_IO_default_uflow+0xe) [0x7856e]
 > /usr/lib64/libc-2.17.so(_IO_getline_info+0xa4) [0x6c514]
 > /usr/lib64/libc-2.17.so(fgets_unlocked+0x3d) [0x7569d]
 > /usr/lib64/libnss_files-2.17.so(internal_getent+0x8f) [0x5b0f]
 > /usr/lib64/libnss_files-2.17.so(_nss_files_getpwuid_r+0x81) [0x6011]
 > /usr/lib64/libc-2.17.so(getpwuid_r+0x15e) [0xbe52e]
 > /usr/lib64/libc-2.17.so(getpwuid+0x76) [0xbdc66]
 > /usr/local/bin/id(main+0x677) [0x20e7]
 > /usr/lib64/libc-2.17.so(__libc_start_main+0xf5) [0x21c05]
 > /usr/local/bin/id(_start+0x29) [0x2478]
close(3</etc/passwd>)                   = 0
 > /usr/lib64/libc-2.17.so(__close_nocancel+0x7) [0xe9e90]
 > /usr/lib64/libc-2.17.so(_IO_file_close_it+0x120) [0x76cc0]
 > /usr/lib64/libc-2.17.so(fclose+0x180) [0x6ac40]
 > /usr/lib64/libnss_files-2.17.so(_nss_files_getpwuid_r+0xe9) [0x6079]
 > /usr/lib64/libc-2.17.so(getpwuid_r+0x15e) [0xbe52e]
 > /usr/lib64/libc-2.17.so(getpwuid+0x76) [0xbdc66]
 > /usr/local/bin/id(main+0x677) [0x20e7]
 > /usr/lib64/libc-2.17.so(__libc_start_main+0xf5) [0x21c05]
 > /usr/local/bin/id(_start+0x29) [0x2478]
uid=1000(vagrant) gid=1000(vagrant) groups=1000(vagrant)
+++ exited with 0 +++

その他の使用例(2)

nginx が 静的コンテンツを返すシステムコールスタックトレースを眺める。イベント駆動なコードはなかなか把握するのが辛いけど、どのフェーズでどのようなシステムコールが呼び出されるかを把握すると、追いかけやすくなる ... かな?

accept4(6<TCP:[782776]>, {sa_family=AF_INET, sin_port=htons(61829), sin_addr=inet_addr("192.168.33.1")}, [110->16], SOCK_NONBLOCK) = 3<TCP:[789563]>
 > /usr/lib64/libc-2.17.so(accept4+0x17) [0xf9787]
 > /usr/sbin/nginx(ngx_event_accept+0xef) [0x40aef]
 > /usr/sbin/nginx(ngx_os_specific_status+0xb61) [0x4a771]
 > /usr/sbin/nginx(ngx_process_events_and_timers+0x6a) [0x401da]
 > /usr/sbin/nginx(ngx_dlerror+0x9e5) [0x47da5]
 > /usr/sbin/nginx(ngx_spawn_process+0x18a) [0x4670a]
 > /usr/sbin/nginx(ngx_dlerror+0xca0) [0x48060]
 > /usr/sbin/nginx(ngx_master_process_cycle+0x46d) [0x491bd]
 > /usr/sbin/nginx(main+0x899) [0x20889]
 > /usr/lib64/libc-2.17.so(__libc_start_main+0xf5) [0x21c05]
 > /usr/sbin/nginx(_start+0x29) [0x20c1e]
epoll_ctl(17<anon_inode:[eventpoll]>, EPOLL_CTL_ADD, 3<TCP:[789563]>, {EPOLLIN|EPOLLRDHUP|EPOLLET, {u32=729518769, u64=139758965330609}}) = 0
 > /usr/lib64/libc-2.17.so(epoll_ctl+0xa) [0xf88ca]
 > /usr/sbin/nginx(ngx_os_specific_status+0x29b) [0x49eab]
 > /usr/sbin/nginx(ngx_handle_read_event+0xa0) [0x40390]
 > /usr/sbin/nginx(ngx_http_init_connection+0x31b) [0x5f2ab]
 > /usr/sbin/nginx(ngx_event_accept+0x473) [0x40e73]
 > /usr/sbin/nginx(ngx_os_specific_status+0xb61) [0x4a771]
 > /usr/sbin/nginx(ngx_process_events_and_timers+0x6a) [0x401da]
 > /usr/sbin/nginx(ngx_dlerror+0x9e5) [0x47da5]
 > /usr/sbin/nginx(ngx_spawn_process+0x18a) [0x4670a]
 > /usr/sbin/nginx(ngx_dlerror+0xca0) [0x48060]
 > /usr/sbin/nginx(ngx_master_process_cycle+0x46d) [0x491bd]
 > /usr/sbin/nginx(main+0x899) [0x20889]
 > /usr/lib64/libc-2.17.so(__libc_start_main+0xf5) [0x21c05]
 > /usr/sbin/nginx(_start+0x29) [0x20c1e]
recvfrom(3<TCP:[789563]>, "GET / HTTP/1.1\r\nHost: 192.168.33.10\r\nUser-Agent: curl/7.52.1\r\nAccept: */*\r\n\r\n", 1024, 0, NULL, NULL) = 77
 > /usr/lib64/libpthread-2.17.so(recv+0x1d) [0xea3d]
 > /usr/sbin/nginx(ngx_unix_recv+0x62) [0x44dc2]
 > /usr/sbin/nginx(ngx_http_process_request+0xb7d) [0x62d2d]
 > /usr/sbin/nginx(ngx_os_specific_status+0xb61) [0x4a771]
 > /usr/sbin/nginx(ngx_process_events_and_timers+0x6a) [0x401da]
 > /usr/sbin/nginx(ngx_dlerror+0x9e5) [0x47da5]
 > /usr/sbin/nginx(ngx_spawn_process+0x18a) [0x4670a]
 > /usr/sbin/nginx(ngx_dlerror+0xca0) [0x48060]
 > /usr/sbin/nginx(ngx_master_process_cycle+0x46d) [0x491bd]
 > /usr/sbin/nginx(main+0x899) [0x20889]
 > /usr/lib64/libc-2.17.so(__libc_start_main+0xf5) [0x21c05]
 > /usr/sbin/nginx(_start+0x29) [0x20c1e]
stat("/usr/share/nginx/html/index.html", {st_mode=S_IFREG|0644, st_size=3700, ...}) = 0
 > /usr/lib64/libc-2.17.so(__xstat64+0x15) [0xe9105]
 > /usr/sbin/nginx(ngx_resolve_addr+0x37a5) [0x3ca75]
 > /usr/sbin/nginx(ngx_open_cached_file+0x336) [0x3d3d6]
 > /usr/sbin/nginx(ngx_http_v2_huff_encode+0x4967) [0x9c5f7]
 > /usr/sbin/nginx(ngx_http_core_content_phase+0x7a) [0x5ba1a]
 > /usr/sbin/nginx(ngx_http_core_run_phases+0x25) [0x55ce5]
 > /usr/sbin/nginx(ngx_http_process_request+0xae) [0x6225e]
 > /usr/sbin/nginx(ngx_http_process_request+0xa8c) [0x62c3c]
 > /usr/sbin/nginx(ngx_os_specific_status+0xb61) [0x4a771]
 > /usr/sbin/nginx(ngx_process_events_and_timers+0x6a) [0x401da]
 > /usr/sbin/nginx(ngx_dlerror+0x9e5) [0x47da5]
 > /usr/sbin/nginx(ngx_spawn_process+0x18a) [0x4670a]
 > /usr/sbin/nginx(ngx_dlerror+0xca0) [0x48060]
 > /usr/sbin/nginx(ngx_master_process_cycle+0x46d) [0x491bd]
 > /usr/sbin/nginx(main+0x899) [0x20889]
 > /usr/lib64/libc-2.17.so(__libc_start_main+0xf5) [0x21c05]
 > /usr/sbin/nginx(_start+0x29) [0x20c1e]
open("/usr/share/nginx/html/index.html", O_RDONLY|O_NONBLOCK) = 4</usr/share/nginx/html/index.html>
 > /usr/lib64/libpthread-2.17.so(__open_nocancel+0x7) [0xee90]
 > /usr/sbin/nginx(ngx_resolve_addr+0x3428) [0x3c6f8]
 > /usr/sbin/nginx(ngx_resolve_addr+0x38fa) [0x3cbca]
 > /usr/sbin/nginx(ngx_open_cached_file+0x1d0) [0x3d270]
 > /usr/sbin/nginx(ngx_http_v2_huff_encode+0x7e7) [0x98477]
 > /usr/sbin/nginx(ngx_http_core_content_phase+0x7a) [0x5ba1a]
 > /usr/sbin/nginx(ngx_http_core_run_phases+0x25) [0x55ce5]
 > /usr/sbin/nginx(ngx_http_internal_redirect+0x129) [0x5c7b9]
 > /usr/sbin/nginx(ngx_http_v2_huff_encode+0x4d28) [0x9c9b8]
 > /usr/sbin/nginx(ngx_http_core_content_phase+0x7a) [0x5ba1a]
 > /usr/sbin/nginx(ngx_http_core_run_phases+0x25) [0x55ce5]
 > /usr/sbin/nginx(ngx_http_process_request+0xae) [0x6225e]
 > /usr/sbin/nginx(ngx_http_process_request+0xa8c) [0x62c3c]
 > /usr/sbin/nginx(ngx_os_specific_status+0xb61) [0x4a771]
 > /usr/sbin/nginx(ngx_process_events_and_timers+0x6a) [0x401da]
 > /usr/sbin/nginx(ngx_dlerror+0x9e5) [0x47da5]
 > /usr/sbin/nginx(ngx_spawn_process+0x18a) [0x4670a]
 > /usr/sbin/nginx(ngx_dlerror+0xca0) [0x48060]
 > /usr/sbin/nginx(ngx_master_process_cycle+0x46d) [0x491bd]
 > /usr/sbin/nginx(main+0x899) [0x20889]
 > /usr/lib64/libc-2.17.so(__libc_start_main+0xf5) [0x21c05]
 > /usr/sbin/nginx(_start+0x29) [0x20c1e]
fstat(4</usr/share/nginx/html/index.html>, {st_mode=S_IFREG|0644, st_size=3700, ...}) = 0
 > /usr/lib64/libc-2.17.so(__fxstat64+0x14) [0xe9154]
 > /usr/sbin/nginx(ngx_resolve_addr+0x3914) [0x3cbe4]
 > /usr/sbin/nginx(ngx_open_cached_file+0x1d0) [0x3d270]
 > /usr/sbin/nginx(ngx_http_v2_huff_encode+0x7e7) [0x98477]
 > /usr/sbin/nginx(ngx_http_core_content_phase+0x7a) [0x5ba1a]
 > /usr/sbin/nginx(ngx_http_core_run_phases+0x25) [0x55ce5]
 > /usr/sbin/nginx(ngx_http_internal_redirect+0x129) [0x5c7b9]
 > /usr/sbin/nginx(ngx_http_v2_huff_encode+0x4d28) [0x9c9b8]
 > /usr/sbin/nginx(ngx_http_core_content_phase+0x7a) [0x5ba1a]
 > /usr/sbin/nginx(ngx_http_core_run_phases+0x25) [0x55ce5]
 > /usr/sbin/nginx(ngx_http_process_request+0xae) [0x6225e]
 > /usr/sbin/nginx(ngx_http_process_request+0xa8c) [0x62c3c]
 > /usr/sbin/nginx(ngx_os_specific_status+0xb61) [0x4a771]
 > /usr/sbin/nginx(ngx_process_events_and_timers+0x6a) [0x401da]
 > /usr/sbin/nginx(ngx_dlerror+0x9e5) [0x47da5]
 > /usr/sbin/nginx(ngx_spawn_process+0x18a) [0x4670a]
 > /usr/sbin/nginx(ngx_dlerror+0xca0) [0x48060]
 > /usr/sbin/nginx(ngx_master_process_cycle+0x46d) [0x491bd]
 > /usr/sbin/nginx(main+0x899) [0x20889]
 > /usr/lib64/libc-2.17.so(__libc_start_main+0xf5) [0x21c05]
 > /usr/sbin/nginx(_start+0x29) [0x20c1e]
setsockopt(3<TCP:[789563]>, SOL_TCP, TCP_CORK, [1], 4) = 0
 > /usr/lib64/libc-2.17.so(setsockopt+0xa) [0xf946a]
 > /usr/sbin/nginx(ngx_tcp_nopush+0x36) [0x44cd6]
 > /usr/sbin/nginx(ngx_linux_sendfile_chain+0x40d) [0x4b58d]
 > /usr/sbin/nginx(ngx_http_write_filter+0x4f0) [0x7f090]
 > /usr/sbin/nginx(ngx_http_write_filter+0x1786) [0x80326]
 > /usr/sbin/nginx(ngx_http_write_filter+0x53cc) [0x83f6c]
 > /usr/sbin/nginx(ngx_http_write_filter+0x86ec) [0x8728c]
 > /usr/sbin/nginx(ngx_http_write_filter+0xbbea) [0x8a78a]
 > /usr/lib64/nginx/modules/ngx_http_xslt_filter_module.so(_init+0x158c) [0x2d2c]
 > /usr/lib64/nginx/modules/ngx_http_image_filter_module.so(_init+0x1b88) [0x3148]
 > /usr/sbin/nginx(ngx_http_write_filter+0xdedf) [0x8ca7f]
 > /usr/sbin/nginx(ngx_http_write_filter+0xe72c) [0x8d2cc]
 > /usr/sbin/nginx(ngx_output_chain+0x8f8) [0x25de8]
 > /usr/sbin/nginx(ngx_http_write_filter+0x1095e) [0x8f4fe]
 > /usr/sbin/nginx(ngx_http_write_filter+0x110fe) [0x8fc9e]
 > /usr/sbin/nginx(ngx_http_output_filter+0x2a) [0x5b53a]
 > /usr/sbin/nginx(ngx_http_v2_huff_encode+0xb8e) [0x9881e]
 > /usr/sbin/nginx(ngx_http_core_content_phase+0x7a) [0x5ba1a]
 > /usr/sbin/nginx(ngx_http_core_run_phases+0x25) [0x55ce5]
 > /usr/sbin/nginx(ngx_http_internal_redirect+0x129) [0x5c7b9]
 > /usr/sbin/nginx(ngx_http_v2_huff_encode+0x4d28) [0x9c9b8]
 > /usr/sbin/nginx(ngx_http_core_content_phase+0x7a) [0x5ba1a]
 > /usr/sbin/nginx(ngx_http_core_run_phases+0x25) [0x55ce5]
 > /usr/sbin/nginx(ngx_http_process_request+0xae) [0x6225e]
 > /usr/sbin/nginx(ngx_http_process_request+0xa8c) [0x62c3c]
 > /usr/sbin/nginx(ngx_os_specific_status+0xb61) [0x4a771]
 > /usr/sbin/nginx(ngx_process_events_and_timers+0x6a) [0x401da]
 > /usr/sbin/nginx(ngx_dlerror+0x9e5) [0x47da5]
 > /usr/sbin/nginx(ngx_spawn_process+0x18a) [0x4670a]
 > /usr/sbin/nginx(ngx_dlerror+0xca0) [0x48060]
 > /usr/sbin/nginx(ngx_master_process_cycle+0x46d) [0x491bd]
 > /usr/sbin/nginx(main+0x899) [0x20889]
 > /usr/lib64/libc-2.17.so(__libc_start_main+0xf5) [0x21c05]
 > /usr/sbin/nginx(_start+0x29) [0x20c1e]
writev(3<TCP:[789563]>, [{iov_base="HTTP/1.1 200 OK\r\nServer: nginx/1.10.2\r\nDate: Wed, 08 Nov 2017 05:33:40 GMT\r\nContent-Type: text/html\r\nContent-Length: 3700\r\nLast-Modified: Mon, 18 Sep 2017 09:18:55 GMT\r\nConnection:"..., iov_len=239}], 1) = 239
 > /usr/lib64/libc-2.17.so(writev+0x17) [0xef1e7]
 > /usr/sbin/nginx(ngx_writev+0x19) [0x45529]
 > /usr/sbin/nginx(ngx_linux_sendfile_chain+0x182) [0x4b302]
 > /usr/sbin/nginx(ngx_http_write_filter+0x4f0) [0x7f090]
 > /usr/sbin/nginx(ngx_http_write_filter+0x1786) [0x80326]
 > /usr/sbin/nginx(ngx_http_write_filter+0x53cc) [0x83f6c]
 > /usr/sbin/nginx(ngx_http_write_filter+0x86ec) [0x8728c]
 > /usr/sbin/nginx(ngx_http_write_filter+0xbbea) [0x8a78a]
 > /usr/lib64/nginx/modules/ngx_http_xslt_filter_module.so(_init+0x158c) [0x2d2c]
 > /usr/lib64/nginx/modules/ngx_http_image_filter_module.so(_init+0x1b88) [0x3148]
 > /usr/sbin/nginx(ngx_http_write_filter+0xdedf) [0x8ca7f]
 > /usr/sbin/nginx(ngx_http_write_filter+0xe72c) [0x8d2cc]
 > /usr/sbin/nginx(ngx_output_chain+0x8f8) [0x25de8]
 > /usr/sbin/nginx(ngx_http_write_filter+0x1095e) [0x8f4fe]
 > /usr/sbin/nginx(ngx_http_write_filter+0x110fe) [0x8fc9e]
 > /usr/sbin/nginx(ngx_http_output_filter+0x2a) [0x5b53a]
 > /usr/sbin/nginx(ngx_http_v2_huff_encode+0xb8e) [0x9881e]
 > /usr/sbin/nginx(ngx_http_core_content_phase+0x7a) [0x5ba1a]
 > /usr/sbin/nginx(ngx_http_core_run_phases+0x25) [0x55ce5]
 > /usr/sbin/nginx(ngx_http_internal_redirect+0x129) [0x5c7b9]
 > /usr/sbin/nginx(ngx_http_v2_huff_encode+0x4d28) [0x9c9b8]
 > /usr/sbin/nginx(ngx_http_core_content_phase+0x7a) [0x5ba1a]
 > /usr/sbin/nginx(ngx_http_core_run_phases+0x25) [0x55ce5]
 > /usr/sbin/nginx(ngx_http_process_request+0xae) [0x6225e]
 > /usr/sbin/nginx(ngx_http_process_request+0xa8c) [0x62c3c]
 > /usr/sbin/nginx(ngx_os_specific_status+0xb61) [0x4a771]
 > /usr/sbin/nginx(ngx_process_events_and_timers+0x6a) [0x401da]
 > /usr/sbin/nginx(ngx_dlerror+0x9e5) [0x47da5]
 > /usr/sbin/nginx(ngx_spawn_process+0x18a) [0x4670a]
 > /usr/sbin/nginx(ngx_dlerror+0xca0) [0x48060]
 > /usr/sbin/nginx(ngx_master_process_cycle+0x46d) [0x491bd]
 > /usr/sbin/nginx(main+0x899) [0x20889]
 > /usr/lib64/libc-2.17.so(__libc_start_main+0xf5) [0x21c05]
 > /usr/sbin/nginx(_start+0x29) [0x20c1e]
sendfile(3<TCP:[789563]>, 4</usr/share/nginx/html/index.html>, [0] => [3700], 3700) = 3700
 > /usr/lib64/libc-2.17.so(sendfile+0xa) [0xedd6a]
 > /usr/sbin/nginx(ngx_linux_sendfile_chain+0x28d) [0x4b40d]
 > /usr/sbin/nginx(ngx_http_write_filter+0x4f0) [0x7f090]
 > /usr/sbin/nginx(ngx_http_write_filter+0x1786) [0x80326]
 > /usr/sbin/nginx(ngx_http_write_filter+0x53cc) [0x83f6c]
 > /usr/sbin/nginx(ngx_http_write_filter+0x86ec) [0x8728c]
 > /usr/sbin/nginx(ngx_http_write_filter+0xbbea) [0x8a78a]
 > /usr/lib64/nginx/modules/ngx_http_xslt_filter_module.so(_init+0x158c) [0x2d2c]
 > /usr/lib64/nginx/modules/ngx_http_image_filter_module.so(_init+0x1b88) [0x3148]
 > /usr/sbin/nginx(ngx_http_write_filter+0xdedf) [0x8ca7f]
 > /usr/sbin/nginx(ngx_http_write_filter+0xe72c) [0x8d2cc]
 > /usr/sbin/nginx(ngx_output_chain+0x8f8) [0x25de8]
 > /usr/sbin/nginx(ngx_http_write_filter+0x1095e) [0x8f4fe]
 > /usr/sbin/nginx(ngx_http_write_filter+0x110fe) [0x8fc9e]
 > /usr/sbin/nginx(ngx_http_output_filter+0x2a) [0x5b53a]
 > /usr/sbin/nginx(ngx_http_v2_huff_encode+0xb8e) [0x9881e]
 > /usr/sbin/nginx(ngx_http_core_content_phase+0x7a) [0x5ba1a]
 > /usr/sbin/nginx(ngx_http_core_run_phases+0x25) [0x55ce5]
 > /usr/sbin/nginx(ngx_http_internal_redirect+0x129) [0x5c7b9]
 > /usr/sbin/nginx(ngx_http_v2_huff_encode+0x4d28) [0x9c9b8]
 > /usr/sbin/nginx(ngx_http_core_content_phase+0x7a) [0x5ba1a]
 > /usr/sbin/nginx(ngx_http_core_run_phases+0x25) [0x55ce5]
 > /usr/sbin/nginx(ngx_http_process_request+0xae) [0x6225e]
 > /usr/sbin/nginx(ngx_http_process_request+0xa8c) [0x62c3c]
 > /usr/sbin/nginx(ngx_os_specific_status+0xb61) [0x4a771]
 > /usr/sbin/nginx(ngx_process_events_and_timers+0x6a) [0x401da]
 > /usr/sbin/nginx(ngx_dlerror+0x9e5) [0x47da5]
 > /usr/sbin/nginx(ngx_spawn_process+0x18a) [0x4670a]
 > /usr/sbin/nginx(ngx_dlerror+0xca0) [0x48060]
 > /usr/sbin/nginx(ngx_master_process_cycle+0x46d) [0x491bd]
 > /usr/sbin/nginx(main+0x899) [0x20889]
 > /usr/lib64/libc-2.17.so(__libc_start_main+0xf5) [0x21c05]
 > /usr/sbin/nginx(_start+0x29) [0x20c1e]
write(16</var/log/nginx/access.log>, "192.168.33.1 - - [08/Nov/2017:05:33:40 +0000] \"GET / HTTP/1.1\" 200 3700 \"-\" \"curl/7.52.1\" \"-\"\n", 94) = 94
 > /usr/lib64/libpthread-2.17.so(__write_nocancel+0x7) [0xe690]
 > /usr/sbin/nginx(ngx_http_parse_chunked+0x20f4) [0x685a4]
 > /usr/sbin/nginx(ngx_http_parse_chunked+0x28aa) [0x68d5a]
 > /usr/sbin/nginx(ngx_http_filter_finalize_request+0x110) [0x5e030]
 > /usr/sbin/nginx(ngx_http_free_request+0xbc) [0x5fccc]
 > /usr/sbin/nginx(ngx_http_block_reading+0x313) [0x608f3]
 > /usr/sbin/nginx(ngx_http_core_content_phase+0xcb) [0x5ba6b]
 > /usr/sbin/nginx(ngx_http_core_run_phases+0x25) [0x55ce5]
 > /usr/sbin/nginx(ngx_http_process_request+0xae) [0x6225e]
 > /usr/sbin/nginx(ngx_http_process_request+0xa8c) [0x62c3c]
 > /usr/sbin/nginx(ngx_os_specific_status+0xb61) [0x4a771]
 > /usr/sbin/nginx(ngx_process_events_and_timers+0x6a) [0x401da]
 > /usr/sbin/nginx(ngx_dlerror+0x9e5) [0x47da5]
 > /usr/sbin/nginx(ngx_spawn_process+0x18a) [0x4670a]
 > /usr/sbin/nginx(ngx_dlerror+0xca0) [0x48060]
 > /usr/sbin/nginx(ngx_master_process_cycle+0x46d) [0x491bd]
 > /usr/sbin/nginx(main+0x899) [0x20889]
 > /usr/lib64/libc-2.17.so(__libc_start_main+0xf5) [0x21c05]
 > /usr/sbin/nginx(_start+0x29) [0x20c1e]
close(4</usr/share/nginx/html/index.html>) = 0
 > /usr/lib64/libpthread-2.17.so(__close_nocancel+0x7) [0xe750]
 > /usr/sbin/nginx(ngx_pool_cleanup_file+0x19) [0x23199]
 > /usr/sbin/nginx(ngx_destroy_pool+0x1e) [0x232ae]
 > /usr/sbin/nginx(ngx_http_free_request+0x121) [0x5fd31]
 > /usr/sbin/nginx(ngx_http_block_reading+0x313) [0x608f3]
 > /usr/sbin/nginx(ngx_http_core_content_phase+0xcb) [0x5ba6b]
 > /usr/sbin/nginx(ngx_http_core_run_phases+0x25) [0x55ce5]
 > /usr/sbin/nginx(ngx_http_process_request+0xae) [0x6225e]
 > /usr/sbin/nginx(ngx_http_process_request+0xa8c) [0x62c3c]
 > /usr/sbin/nginx(ngx_os_specific_status+0xb61) [0x4a771]
 > /usr/sbin/nginx(ngx_process_events_and_timers+0x6a) [0x401da]
 > /usr/sbin/nginx(ngx_dlerror+0x9e5) [0x47da5]
 > /usr/sbin/nginx(ngx_spawn_process+0x18a) [0x4670a]
 > /usr/sbin/nginx(ngx_dlerror+0xca0) [0x48060]
 > /usr/sbin/nginx(ngx_master_process_cycle+0x46d) [0x491bd]
 > /usr/sbin/nginx(main+0x899) [0x20889]
 > /usr/lib64/libc-2.17.so(__libc_start_main+0xf5) [0x21c05]
 > /usr/sbin/nginx(_start+0x29) [0x20c1e]
setsockopt(3<TCP:[789563]>, SOL_TCP, TCP_CORK, [0], 4) = 0
 > /usr/lib64/libc-2.17.so(setsockopt+0xa) [0xf946a]
 > /usr/sbin/nginx(ngx_tcp_push+0x36) [0x44d36]
 > /usr/sbin/nginx(ngx_http_block_reading+0xac1) [0x610a1]
 > /usr/sbin/nginx(ngx_http_core_content_phase+0xcb) [0x5ba6b]
 > /usr/sbin/nginx(ngx_http_core_run_phases+0x25) [0x55ce5]
 > /usr/sbin/nginx(ngx_http_process_request+0xae) [0x6225e]
 > /usr/sbin/nginx(ngx_http_process_request+0xa8c) [0x62c3c]
 > /usr/sbin/nginx(ngx_os_specific_status+0xb61) [0x4a771]
 > /usr/sbin/nginx(ngx_process_events_and_timers+0x6a) [0x401da]
 > /usr/sbin/nginx(ngx_dlerror+0x9e5) [0x47da5]
 > /usr/sbin/nginx(ngx_spawn_process+0x18a) [0x4670a]
 > /usr/sbin/nginx(ngx_dlerror+0xca0) [0x48060]
 > /usr/sbin/nginx(ngx_master_process_cycle+0x46d) [0x491bd]
 > /usr/sbin/nginx(main+0x899) [0x20889]
 > /usr/lib64/libc-2.17.so(__libc_start_main+0xf5) [0x21c05]
 > /usr/sbin/nginx(_start+0x29) [0x20c1e]
recvfrom(3<TCP:[789563]>, "", 1024, 0, NULL, NULL) = 0
 > /usr/lib64/libpthread-2.17.so(recv+0x1d) [0xea3d]
 > /usr/sbin/nginx(ngx_unix_recv+0x62) [0x44dc2]
 > /usr/sbin/nginx(ngx_http_process_request+0x14fa) [0x636aa]
 > /usr/sbin/nginx(ngx_event_process_posted+0x53) [0x40783]
 > /usr/sbin/nginx(ngx_dlerror+0x9e5) [0x47da5]
 > /usr/sbin/nginx(ngx_spawn_process+0x18a) [0x4670a]
 > /usr/sbin/nginx(ngx_dlerror+0xca0) [0x48060]
 > /usr/sbin/nginx(ngx_master_process_cycle+0x46d) [0x491bd]
 > /usr/sbin/nginx(main+0x899) [0x20889]
 > /usr/lib64/libc-2.17.so(__libc_start_main+0xf5) [0x21c05]
 > /usr/sbin/nginx(_start+0x29) [0x20c1e]
close(3<TCP:[789563]>)                  = 0
 > /usr/lib64/libpthread-2.17.so(__close_nocancel+0x7) [0xe750]
 > /usr/sbin/nginx(ngx_close_connection+0x130) [0x30800]
 > /usr/sbin/nginx(ngx_http_close_connection+0x50) [0x5ea30]
 > /usr/sbin/nginx(ngx_event_process_posted+0x53) [0x40783]
 > /usr/sbin/nginx(ngx_dlerror+0x9e5) [0x47da5]
 > /usr/sbin/nginx(ngx_spawn_process+0x18a) [0x4670a]
 > /usr/sbin/nginx(ngx_dlerror+0xca0) [0x48060]
 > /usr/sbin/nginx(ngx_master_process_cycle+0x46d) [0x491bd]
 > /usr/sbin/nginx(main+0x899) [0x20889]
 > /usr/lib64/libc-2.17.so(__libc_start_main+0xf5) [0x21c05]
 > /usr/sbin/nginx(_start+0x29) [0x20c1e]

ソケットプログラミングのお勉強になる

感想

  • ソースコードリーディングがはかどる
  • 障害や不具合解決でもはかどりそう。事例ができたら紹介したい
  • だがしかし、experimental なのでディストリビューションではサポートされない可能性が高いため、ビルドが面倒だ

脇道の話: コミットの歴史

strace-plus として fork されていたコードが本家に還元されたという経緯があるらしい

github.com

Based on the code that was originally taken from strace-plus of Philip J. Guo. とのこと

だがしかし strace-plus は既に閉じてしまったプロジェクトだ https://code.google.com/archive/p/strace-plus/

Disclaimer: As of Jan 2012, this project is unsupported. Features from strace-plus have been merged into the official strace as the -k option, starting from version 4.9."