debugging server with strace

debugging server with strace

Yoshinari Takaoka@mumumu

Agenda

● 自己紹介● strace basic● システムコールについて● straceによるサーバデバッグの勘所● まとめ

アプリケーションエンジニアであっても、 strace によるサーバのデバッグをわかった気になることが目標

自己紹介

自己紹介(1)

● Yoshinari Takaoka @mumumu● ソフトウェアエンジニア

Java で Webアプリ → 組込みソフト屋

→ EC屋 → 現職● 広島県出身

自己紹介(2)

● C, C++, Java, JavaScript, PHP, Python ● Linux (Red Hat, Debian, KDE)● Translator, PHP Manual Maintainer

http://producingoss.com/

http://www.oreilly.co.jp/books/9784873114125/

http://producingoss.com/

http://www.oreilly.co.jp/books/9784873114125/

strace basic

strace って? (1)

● system call tracer for Linux

http://sourceforge.net/projects/strace/

実行中のソフトウェアが呼び出している「システムコール」をリアルタイムに追いかけられるツール


システムコール?

システムコールって? (1)

● 特権が必要なCPU命令の実行を kernel 様にお願いするための仕組み

ハードウェア操作

割り込み … etc

● ユーザー視点だとただのC言語の関数呼び出し

kernel の機能(サービス)を呼び出す関数と言い換えてもよいhttp://www.atmarkit.co.jp/ait/articles/1111/16/news161.html

http://www.atmarkit.co.jp/ait/articles/1111/16/news161.html

strace って? (2)

● system call tracer for Linux


実行中のソフトウェアの(kernelの機能を実行している) 関数呼び出しをリアルタイムに追いかけられるツール

● 追いかけられる関数の出力はC言語の形式

● 対象とするソフトウェアの動きを無停止で見ることができる

サーバの障害解析

アプリレベルでのボトルネックの調査 ...などに重宝

…. 要するにデバッグツール。


Demo

sudo strace -T -tt -p XX -f -e trace=network,file,read,write

● 上記を実際にやってみる● 実行中のプロセスにアタッチできる● 出力される1行1行がシステムコール

● けど多分1行1行が何がなんだかわかんない

→ システムコールをもっと知る必要がある

システムコールって?(2)

● システムコールは kernel の機能を呼び出すための関数呼び出し

● Linux のシステムコールは2.6系でも300位ある

ここでは、サーバのデバッグに役立つものを解説

[クライアント|サーバ] の基本的な動きを知っておくとわかりやすい (Unixプログラミングに親しむと尚良い)

● 知らないシステムコールは...

「manpage of システムコール名」でググるか

Linux上で「man 2 システムコール名」

サーバの基本的な動き

int sock = socket(PF_INET, SOCK_STREAM);

bind(sock, addr);

listen(sock);

while(1) {

// 確立済みの接続を取り出す

int new_sock = accept(sock, &addr);

char buf[1024]

// クライアントから読む(受信)

size_t size = read(new_sock, buf, 1024);

if (size == 0) {

close(sock); // 送信がなければ何もしない

} else {

　 // クライアントに書く(送信)

write(new_sock, buf, size);

}

}

クライアントの基本的な動き

int sock = socket(PF_INET, SOCK_STREAM);

connect(sock, addr); // 接続

write(sock, “ping”); // サーバに送信

char response[100];

read(sock, response, 100); // サーバから受信

基本的なシステムコール(ネットワーク)

● ソケットを作る/接続する(クライアント)

socket / connect

● ポートで接続を待つ / 確立した接続をソケットとして取得(サーバ)

listen / accept

● ソケットから何か読む(受信)

recv / recvfrom / recvmsg / read系関数 ... etc

● ソケットに何か書く(送信)

send / sendto / sendmsg / write系関数 ... etc

基本的なシステムコール(ネットワーク)(2)

● ソケットの状態変化を待つ

select/poll/epoll_wait … etc

● 接続を閉じる

shutdown/close ... etc

基本的なシステムコール(ファイル)

● ファイルを開く/閉じる

open / close

● ファイルの様子を見る

stat / fstat / lstat ... etc

● ファイルから何か読む

read / readv / pread / preadv ... etc

● ファイルに何か書く

write / writev / pwrite / pwritev ... etc

基本的なシステムコール(その他)

● ファイルディスクリプタをいろいろ操作

fcntl / ioctl / epoll_ctl … etc

● メモリ関係

mmap / munmap ...etc

● 時刻を取得

gettimeofday … etc

番外編: ファイルディスクリプタについて

● ファイルやソケットを開いたとき、それらを識別する0以上の数値をファイルディスクリプタ(記述子)と呼ぶ

int fd = open(“hoge.txt”, O_RDONLY);

ssize_t readbyte = read(fd, buffer, byte);

ファイルやソケットに読み書きするときは、このファイルディスクリプタが必ず引数になる。

このことが、strace の出力を読むときに重要な手がかりになる。

よく使うstraceのコマンドラインオプション

strace のオプション(1)● 以下を覚えておけば実戦である程度困らない● 詳しくは man strace

-tt

マイクロ秒単位のタイムスタンプを付加

-T

各システムコールにかかった時間を記録

-p

　アタッチするプロセスIDを指定

straceのオプション(2)-f

　fork した子[プロセス|スレッド]も追跡する

-e trace=XXX

追跡するシステムコールや追跡の仕方を指定。

これで情報が不足するようなら指定せずに試してみる

例) -e trace=network, file, read, write

ファイルとネットワーク系のシステムコールを

追跡する。よく使います

straceのオプション(3)

-o filename

標準エラー出力(デフォルト)ではなく、ファイル

にトレースを出力する

高トラフィックのサーバだとすぐにサイズが巨大になるので取扱注意。

これでstraceの基礎はばっちり！(｀ー´)

straceによるサーバデバッグの勘所

勘所は4つ

● 読みづらいので、出力を読むコツをつかむ● 子プロセスに根気よく実行● 異常なシステムコールの戻り値に注目● 遅い、または詰まった動きに注目

strace の出力を読むコツ

● はじめと終わりをつかむ● 同じファイルディスクリプタを追う● アプリの動きを知ってなくても読めるが、知っていた

方が流れを推測しやすい

はじめと終わりをつかむ

● Webサーバの場合、はじめは接続をaccept してリクエストの中身を受け取るところから

終わりはレスポンスを返すところ● HTMLを吐く部分とか。QUERY_STRING とかある部分とか。いろいろ。

はじめと終わりをつかむ

23:44:43.704135 read(8, "\f\0QUERY_STRINGT\2u=hogehoge...."..., 2648) = 2648 <0.000015>

… snip

23:44:43.798581 writev(8, [{"HTTP/1.1", 8}, {" ", 1}, {"200 OK", 6}, {"\r\n", 2}, {"Content-Type", 12}, {": ", 2}, {"text/html; charset=utf-8", 24}, {"\r\n", 2}, {"P3P", 3}, {": ", 2}, {"\r\n", 2}, {"Pragma", 6}, {": ", 2}, {"no-cache", 8}, {"\r\n", 2}, {"Cache-Control", 13}, {": ", 2}, {"private, no-cache, no-cache=\"Set"..., 58}, {"\r\n", 2}, {"Set-Cookie", 10}, {": ", 2}, {"\r\n", 2}, {"\r\n", 2}], 25) = 281 <0.000030>

23:44:43.798747 write(8, "<html><head><style>html,body{mar"..., 1641) = 1641 <0.000022>

同じファイルディスクリプタを追う

● 同じファイルディスクリプタを使っているトレースは一連の処理。

● 複数のリクエストのトレースが錯綜する中で、ファイルディスクリプタは有用な手段

同じファイルディスクリプタを追う(2)23:31:15.410761 sendto(15, "\r\n$7\r\nhoge foo bar\r\n$44\r\nfoo.bar.s"..., 68, 0, NULL, 0) = 68 <0.000022>

23:31:15.410829 recvfrom(15, "hogehoge\r\n", 4096, 0, NULL, NULL) = 4 <0.000263>

23:31:15.412355 sendto(16, "*2\r\n$7\r\hoge foo bar\r\n$44\r\nhogehoge.s"..., 68, 0, NULL, 0) = 68 <0.000021>

23:31:15.412422 recvfrom(16, "*0\r\n", 4096, 0, NULL, NULL) = 4 <0.000350>

23:31:15.413929 socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 49 <0.001255>

23:31:15.415271 connect(49, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("XXX.XXX.XXX.XXX")}, 16) = -1EINPROGRESS (Operation now in progress) <0.000026>

2:31:15.415705 socket(PF_INET, SOCK_STREAM, IPPROTO_TCP) = 50 <0.000016>

3:31:15.415798 connect(50, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("XXX.XXX.XX.XX")}, 16) = -1 EINPROGRESS (Operation now in progress) <0.000030>

23:31:15.418609 getsockopt(49, SOL_SOCKET, SO_ERROR, [127367220803141632], [4]) = 0 <0.000011>

23:31:15.418672 getpeername(49, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("XX.XX.XX.XX")}, [12703950620852240]) = 0 <0.000010>

23:31:15.418715 getsockname(49, {sa_family=AF_INET, sin_port=htons(38568), sin_addr=inet_addr("XX.XX.XX.X")},[12147897053468426256]) = 0 <0.000008>

23:31:15.418859 sendto(49, "POST /hoge HTTP/1.1\r\nHost: hoge"..., 818, MSG_NOSIGNAL, NULL, 0) = 818 <0.000025>

23:31:15.419129 getsockopt(50, SOL_SOCKET, SO_ERROR, [127238371784261632], [4]) = 0 <0.000009>

23:31:15.419184 getpeername(50, {sa_family=AF_INET, sin_port=htons(80), sin_addr=inet_addr("XXX.XX.XX.XX")}, [12703950620852240]) = 0 <0.000008>

23:31:15.419224 getsockname(50, {sa_family=AF_INET, sin_port=htons(50707), sin_addr=inet_addr("XXX.XXX.XX.X")}, [1424826340699275280]) = 0 <0.000009>

23:31:15.419435 sendto(50, "POST /?foo=bar HTTP/1.1\r\nHos"..., 759, MSG_NOSIGNAL, NULL, 0) = 759 <0.000020>

23:31:15.435741 recvfrom(49, "HTTP/1.1 204 No Content\r\n"..., 16384, 0, NULL, NULL) = 305 <0.000011>

23:31:15.440848 recvfrom(50, "HTTP/1.1 200 OK\r\nServer: ...."..., 16384, 0, NULL, NULL) = 822 <0.000012>

子プロセスに根気よく実行

● サーバの親プロセスは基本fork(spawn)するのが役目なので、子プロセスのプロセスID を -p に指定

それでもプロセスやスレッドの忙しさにムラがあるなどの理由でなかなか動きが把握しづらい場合も多い (うまい方法ないですかね....)

おかしな動きが見つかったらラッキーくらいの気楽な気持ちで実行するのが吉

子プロセスに根気よく実行

www-data 6331 681 0 14:54 ? 00:00:04 /usr/sbin/apache2 -k start








www-data 15708 681 0 8月23 ? 00:00:16 /usr/sbin/apache2 -k start






www-data 27070 681 0 8月24 ? 00:00:09 /usr/sbin/apache2 -k start●

異常なシステムコールの戻り値に注目(1)

● システムコールが異常時に返す値は様々だが、strace の出力にはエラー時に理由もついてくるので、理由に注目。

● No such file or directory はよくある話

● 普段のサーバ(アプリ)の動きを把握しておこう

異常なシステムコールの戻り値に注目(2)[pid 15033] 04:39:44.457978 accept(4, 0x7ffff7b82700, [16902192126610112528]) = -1 EMFILE (Too many open files)

[pid 15033] 04:39:44.458035 open("/var/log/hoge/hoge.log", O_WRONLY|O_CREAT|O_APPEND, 0666) = -1 EMFILE (Too many open files)

[pid 15033] 04:39:44.458071 write(493, "foobar\r\n"..., 115) = 115

[pid 15033] 04:39:44.458110 epoll_ctl(3, EPOLL_CTL_MOD, 493, {EPOLLIN, {u32=493, u64=493}}) = 0

[pid 15033] 04:39:44.458139 read(361, "hogefuga\r\n"..., 16384) = 68

[pid 15033] 04:39:44.458171 epoll_ctl(3, EPOLL_CTL_MOD, 361, {EPOLLIN|EPOLLOUT, {u32=361, u64=361}}) = 0

[pid 15033] 04:39:44.458201 epoll_wait(3, {{EPOLLIN, {u32=4, u64=4}}, {EPOLLOUT, {u32=361, u64=361}}, {EPOLLIN, {u32=190, u64=190}}}, 10240, 8) = 3

[pid 15033] 04:39:44.458231 accept(4, 0x7ffff7b82700, [16902192126610112528]) = -1 EMFILE (Too many open files)


[pid 15033] 04:39:44.458311 write(361, "hogehoge\r\n", 4) = 4

[pid 15033] 04:39:44.458369 epoll_ctl(3, EPOLL_CTL_MOD, 361, {EPOLLIN, {u32=361, u64=361}}) = 0

[pid 15033] 04:39:44.458416 read(190, "hogehoge\r\n"..., 16384) = 160

[pid 15033] 04:39:44.458460 epoll_ctl(3, EPOLL_CTL_MOD, 190, {EPOLLIN|EPOLLOUT, {u32=190, u64=190}}) = 0

[pid 15033] 04:39:44.458513 epoll_wait(3, {{EPOLLIN, {u32=4, u64=4}}, {EPOLLOUT, {u32=190, u64=190}}, {EPOLLIN, {u32=493, u64=493}}}, 10240, 8) = 3

[pid 15033] 04:39:44.458548 accept(4, 0x7ffff7b82700, [16902192126610112528]) = -1 EMFILE (Too many open files)


[pid 15033] 04:39:44.458613 write(190, "hogehoge\r\n", 5) = 5

遅い、または詰まった動きに注目(1)

● Operation now in Progress とか

<unfinished …>

という類のメッセージが同じ処理でくり返されており、処理が進んでいないようなら要注目

● リアルタイムで見ていると、川のように流れているトレースが一瞬詰まる瞬間が見つかることも。

遅い、または詰まった動きに注目(2)[pid 22331] 03:55:56.482860 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 9

[pid 22331] 03:55:56.483255 connect(9, {sa_family=AF_INET, sin_port=htons(XXXX), sin_addr=inet_addr("127.0.0.1")}, 16) = 0

[pid 22331] 03:55:56.483406 sendto(9, "hogehoge\r\n", 23, 0, NULL, 0) = 23

[pid 22331] 03:55:56.483469 recvfrom(9, "+foobar\r\n", 4096, 0, NULL, NULL) = 5

....snip

[pid 22331] 03:55:56.487400 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 13

[pid 22331] 03:55:56.487635 connect(13, {sa_family=AF_INET, sin_port=htons(XXXX), sin_addr=inet_addr("XX.XX.XX.XX")}, 16) = -1 EINPROGRESS (Operation now in progress)

[pid 22331] 03:55:56.487873 getsockopt(13, SOL_SOCKET, SO_ERROR, [153356102270976000], [4]) = 0

[pid 22331] 03:55:56.487931 sendto(13, "hogehogehogehoge"..., 61, 0, NULL, 0) = 61

[pid 22331] 03:55:56.488534 recvfrom(13, "fugafugafugafuga"..., 4096, 0, NULL, NULL) = 76


[pid 22331] 03:55:56.488855 connect(14, {sa_family=AF_INET, sin_port=htons(XXXX), sin_addr=inet_addr("XX.XX.XX.XX")}, 16) = -1 EINPROGRESS (Operation now in progress)

[pid 22331] 03:55:56.488987 getsockopt(14, SOL_SOCKET, SO_ERROR, [153356102270976000], [4]) = 0

[pid 22331] 03:55:56.489039 sendto(14, "foobar\r\n"..., 59, 0, NULL, 0) = 59

[pid 22331] 03:55:56.489353 recvfrom(14, "hogehoge\r\n"..., 4096, 0, NULL, NULL) = 73


[pid 22331] 03:55:56.491986 connect(15, {sa_family=AF_INET, sin_port=htons(XXXX), sin_addr=inet_addr("XX.XX.XX.XX")}, 16) = 0

[pid 22331] 03:55:56.492135 sendto(15, "fooba\r\n"..., 51, 0, NULL, 0) = 51

[pid 22331] 03:55:56.492177 recvfrom(15, <unfinished ...>

遅い、または詰まった動きに注目(3)

● タイムスタンプを見てどう見ても遅いものも注意● サーバなので、応答をちゃんと返せているかも注目

[pid 1710] 14:06:19.006556 futex(0x619064, FUTEX_WAIT_PRIVATE, 17, NULL <unfinished ...>

[pid 1709] 14:06:19.006627 futex(0x619b60, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>



まとめ

● strace は無停止でのデバッグに重宝

動きが変なサーバを見つけたら strace してみる

変なのが見つかればラッキーくらいのつもりで● 基本的なシステムコールを把握しよう● よく使うオプションは限られている● 出力を読むには少しコツがいるが、勘所をおさ

えれば大丈夫

Questions?

debugging server with strace

Education

Transcript of debugging server with strace