![システムコールって?(2)
● システムコールは kernel の機能を呼び出すための関数呼び
出し
● Linux のシステムコールは2.6系でも300位ある
ここでは、サーバのデバッグに役立つものを解説
[クライアント|サーバ] の基本的な動きを知っておくとわかりや
すい (Unixプログラミングに親しむと尚良い)
● 知らないシステムコールは...
「manpage of システムコール名」でググるか
Linux上で 「man 2 システムコール名」](https://image.slidesharecdn.com/debuggingserverwithstrace-131011060415-phpapp01/85/debugging-server-with-strace-12-320.jpg)
![サーバの基本的な動き
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);
}
}](https://image.slidesharecdn.com/debuggingserverwithstrace-131011060415-phpapp01/85/debugging-server-with-strace-13-320.jpg)
![クライアントの基本的な動き
int sock = socket(PF_INET, SOCK_STREAM);
connect(sock, addr); // 接続
write(sock, “ping”); // サーバに送信
char response[100];
read(sock, response, 100); // サーバから受信](https://image.slidesharecdn.com/debuggingserverwithstrace-131011060415-phpapp01/85/debugging-server-with-strace-14-320.jpg)
![straceのオプション(2)
-f
fork した子[プロセス|スレッド]も追跡する
-e trace=XXX
追跡するシステムコールや追跡の仕方を指定。
これで情報が不足するようなら指定せずに試してみる
例) -e trace=network, file, read, write
ファイルとネットワーク系のシステムコールを
追跡する。よく使います](https://image.slidesharecdn.com/debuggingserverwithstrace-131011060415-phpapp01/85/debugging-server-with-strace-22-320.jpg)
![はじめと終わりをつかむ
23:44:43.704135 read(8, "f0QUERY_STRINGT2u=hogehoge...."...,
2648) = 2648 <0.000015>
… snip
23:44:43.798581 writev(8, [{"HTTP/1.1", 8}, {" ", 1}, {"200 OK", 6},
{"rn", 2}, {"Content-Type", 12}, {": ", 2}, {"text/html; charset=utf-8", 24},
{"rn", 2}, {"P3P", 3}, {": ", 2}, {"rn", 2}, {"Pragma", 6}, {": ", 2},
{"no-cache", 8}, {"rn", 2}, {"Cache-Control", 13}, {": ", 2}, {"private,
no-cache, no-cache="Set"..., 58}, {"rn", 2}, {"Set-Cookie", 10}, {": ",
2}, {"rn", 2}, {"rn", 2}], 25) = 281 <0.000030>
23:44:43.798747 write(8, "<html><head><style>html,body{mar"...,
1641) = 1641 <0.000022>](https://image.slidesharecdn.com/debuggingserverwithstrace-131011060415-phpapp01/85/debugging-server-with-strace-29-320.jpg)
![同じファイルディスクリプタを追う(2)
23:31:15.410761 sendto(15, "rn$7rnhoge foo barrn$44rnfoo.bar.s"..., 68, 0, NULL, 0) = 68 <0.000022>
23:31:15.410829 recvfrom(15, "hogehogern", 4096, 0, NULL, NULL) = 4 <0.000263>
23:31:15.412355 sendto(16, "*2rn$7rhoge foo barrn$44rnhogehoge.s"..., 68, 0, NULL, 0) = 68 <0.000021>
23:31:15.412422 recvfrom(16, "*0rn", 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.1rnHost: 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.1rnHos"..., 759, MSG_NOSIGNAL, NULL, 0) = 759 <0.000020>
23:31:15.435741 recvfrom(49, "HTTP/1.1 204 No Contentrn"..., 16384, 0, NULL, NULL) = 305 <0.000011>
23:31:15.440848 recvfrom(50, "HTTP/1.1 200 OKrnServer: ...."..., 16384, 0, NULL, NULL) = 822 <0.000012>](https://image.slidesharecdn.com/debuggingserverwithstrace-131011060415-phpapp01/85/debugging-server-with-strace-31-320.jpg)
![異常なシステムコールの戻り値に注目(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, "foobarrn"..., 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, "hogefugarn"..., 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.458274 open("/var/log/hoge/hoge.log", O_WRONLY|O_CREAT|O_APPEND, 0666) = -1 EMFILE (Too many
open files)
[pid 15033] 04:39:44.458311 write(361, "hogehogern", 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, "hogehogern"..., 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.458582 open("/var/log/hoge/hoge.log", O_WRONLY|O_CREAT|O_APPEND, 0666) = -1 EMFILE (Too many
open files)
[pid 15033] 04:39:44.458613 write(190, "hogehogern", 5) = 5](https://image.slidesharecdn.com/debuggingserverwithstrace-131011060415-phpapp01/85/debugging-server-with-strace-35-320.jpg)
![遅い、または詰まった動きに注目(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, "hogehogern", 23, 0, NULL, 0) = 23
[pid 22331] 03:55:56.483469 recvfrom(9, "+foobarrn", 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.488633 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 14
[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, "foobarrn"..., 59, 0, NULL, 0) = 59
[pid 22331] 03:55:56.489353 recvfrom(14, "hogehogern"..., 4096, 0, NULL, NULL) = 73
[pid 22331] 03:55:56.491714 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 15
[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, "foobarn"..., 51, 0, NULL, 0) = 51
[pid 22331] 03:55:56.492177 recvfrom(15, <unfinished ...>](https://image.slidesharecdn.com/debuggingserverwithstrace-131011060415-phpapp01/85/debugging-server-with-strace-37-320.jpg)
![遅い、または詰まった動きに注目(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 ...>
[pid 1708] 14:06:19.006645 futex(0x619b60, FUTEX_WAIT_PRIVATE, 2,
NULL <unfinished ...>
[pid 1706] 14:06:19.006662 futex(0x619b60, FUTEX_WAIT_PRIVATE, 2,
NULL <unfinished ...>](https://image.slidesharecdn.com/debuggingserverwithstrace-131011060415-phpapp01/85/debugging-server-with-strace-38-320.jpg)
More Related Content
What's hot (20)
Similar to debugging server with strace (20)
![[data analytics showcase] B12: サーバー1,000台を監視するということ by 株式会社インサイトテクノロジー 小幡 一郎](https://cdn.slidesharecdn.com/ss_thumbnails/zwxv3e5eq2onvtifzkda-signature-1379033641429794afbc9d6c48d9c7cc5945545725d7bf5772715883640ebcaa-poli-161011071522-thumbnail.jpg?width=560&fit=bounds)
Recently uploaded (6)
debugging server with strace
- 1. debugging server with strace Yoshinari Takaoka @mumumu
- 2. Agenda ● 自己绍介 ● strace basic ● システムコールについて ● straceによるサーバデバッグの勘所 ● まとめ アプリケーションエンジニアであっても、 strace によ るサーバのデバッグをわかった気になることが目標
- 3. 自己绍介
- 4. 自己绍介(1) ● Yoshinari Takaoka @mumumu ● ソフトウェアエンジニア Java で Webアプリ → 組込みソフト屋 → EC屋 → 現職 ● 広島県出身
- 5. 自己绍介(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/
- 6. strace basic
- 7. strace って? (1) ● system call tracer for Linux http://sourceforge.net/projects/strace/ 実行中のソフトウェアが呼び出している「システム コール」をリアルタイムに追いかけられるツール
- 8. システムコール?
- 9. システムコールって? (1) ● 特権が必要なCPU命令の実行を kernel 様にお願 いするための仕組み ハードウェア操作 割り込み … etc ● ユーザー視点だとただのC言語の関数呼び出し kernel の機能(サービス)を呼び出す関数と言い換 えてもよい http://www.atmarkit.co.jp/ait/articles/1111/16/news161.html
- 10. strace って? (2) ● system call tracer for Linux http://sourceforge.net/projects/strace/ 実行中のソフトウェアの(kernelの機能を実行している) 関数呼び出しをリア ルタイムに追いかけられるツール ● 追いかけられる関数の出力はC言語の形式 ● 対象とするソフトウェアの動きを無停止で見ることができる サーバの障害解析 アプリレベルでのボトルネックの調査 ...などに重宝 …. 要するにデバッグツール。
- 11. Demo sudo strace -T -tt -p XX -f -e trace=network,file,read,write ● 上記を実際にやってみる ● 実行中のプロセスにアタッチできる ● 出力される1行1行がシステムコール ● けど多分1行1行が何がなんだかわかんない → システムコールをもっと知る必要がある
- 12. システムコールって?(2) ● システムコールは kernel の機能を呼び出すための関数呼び 出し ● Linux のシステムコールは2.6系でも300位ある ここでは、サーバのデバッグに役立つものを解説 [クライアント|サーバ] の基本的な動きを知っておくとわかりや すい (Unixプログラミングに親しむと尚良い) ● 知らないシステムコールは... 「manpage of システムコール名」でググるか Linux上で 「man 2 システムコール名」
- 13. サーバの基本的な動き 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); } }
- 14. クライアントの基本的な動き int sock = socket(PF_INET, SOCK_STREAM); connect(sock, addr); // 接続 write(sock, “ping”); // サーバに送信 char response[100]; read(sock, response, 100); // サーバから受信
- 15. 基本的なシステムコール(ネットワーク) ● ソケットを作る/接続する(クライアント) socket / connect ● ポートで接続を待つ / 確立した接続をソケットとして取得(サーバ) listen / accept ● ソケットから何か読む(受信) recv / recvfrom / recvmsg / read系関数 ... etc ● ソケットに何か書く(送信) send / sendto / sendmsg / write系関数 ... etc
- 16. 基本的なシステムコール(ネットワーク)(2) ● ソケットの状態変化を待つ select/poll/epoll_wait … etc ● 接続を閉じる shutdown/close ... etc
- 17. 基本的なシステムコール(ファイル) ● ファイルを開く/閉じる open / close ● ファイルの様子を見る stat / fstat / lstat ... etc ● ファイルから何か読む read / readv / pread / preadv ... etc ● ファイルに何か書く write / writev / pwrite / pwritev ... etc
- 18. 基本的なシステムコール(その他) ● ファイルディスクリプタをいろいろ操作 fcntl / ioctl / epoll_ctl … etc ● メモリ関係 mmap / munmap ...etc ● 時刻を取得 gettimeofday … etc
- 19. 番外編: ファイルディスクリプタについて ● ファイルやソケットを開いたとき、それらを識別する0 以上の数値をファイルディスクリプタ(記述子)と呼ぶ int fd = open(“hoge.txt”, O_RDONLY); ssize_t readbyte = read(fd, buffer, byte); ファイルやソケットに読み書きするときは、このファイル ディスクリプタが必ず引数になる。 このことが、strace の出力を読むときに重要な手が かりになる。
- 21. strace のオプション(1) ● 以下を覚えておけば実戦である程度困らない ● 詳しくは man strace -tt マイクロ秒単位のタイムスタンプを付加 -T 各システムコールにかかった時間を記録 -p アタッチするプロセスIDを指定
- 22. straceのオプション(2) -f fork した子[プロセス|スレッド]も追跡する -e trace=XXX 追跡するシステムコールや追跡の仕方を指定。 これで情報が不足するようなら指定せずに試してみる 例) -e trace=network, file, read, write ファイルとネットワーク系のシステムコールを 追跡する。よく使います
- 23. straceのオプション(3) -o filename 標準エラー出力(デフォルト)ではなく、ファイル にトレースを出力する 高トラフィックのサーバだとすぐにサイズが巨大に なるので取扱注意。
- 26. 勘所は4つ ● 読みづらいので、出力を読むコツをつかむ ● 子プロセスに根気よく実行 ● 異常なシステムコールの戻り値に注目 ● 遅い、または詰まった動きに注目
- 27. strace の出力を読むコツ ● はじめと終わりをつかむ ● 同じファイルディスクリプタを追う ● アプリの動きを知ってなくても読めるが、知っていた 方が流れを推測しやすい
- 28. はじめと終わりをつかむ ● Webサーバの場合、はじめは接続をaccept してリ クエストの中身を受け取るところから 終わりはレスポンスを返すところ ● HTMLを吐く部分とか。QUERY_STRING とかある 部分とか。いろいろ。
- 29. はじめと終わりをつかむ 23:44:43.704135 read(8, "f0QUERY_STRINGT2u=hogehoge...."..., 2648) = 2648 <0.000015> … snip 23:44:43.798581 writev(8, [{"HTTP/1.1", 8}, {" ", 1}, {"200 OK", 6}, {"rn", 2}, {"Content-Type", 12}, {": ", 2}, {"text/html; charset=utf-8", 24}, {"rn", 2}, {"P3P", 3}, {": ", 2}, {"rn", 2}, {"Pragma", 6}, {": ", 2}, {"no-cache", 8}, {"rn", 2}, {"Cache-Control", 13}, {": ", 2}, {"private, no-cache, no-cache="Set"..., 58}, {"rn", 2}, {"Set-Cookie", 10}, {": ", 2}, {"rn", 2}, {"rn", 2}], 25) = 281 <0.000030> 23:44:43.798747 write(8, "<html><head><style>html,body{mar"..., 1641) = 1641 <0.000022>
- 31. 同じファイルディスクリプタを追う(2) 23:31:15.410761 sendto(15, "rn$7rnhoge foo barrn$44rnfoo.bar.s"..., 68, 0, NULL, 0) = 68 <0.000022> 23:31:15.410829 recvfrom(15, "hogehogern", 4096, 0, NULL, NULL) = 4 <0.000263> 23:31:15.412355 sendto(16, "*2rn$7rhoge foo barrn$44rnhogehoge.s"..., 68, 0, NULL, 0) = 68 <0.000021> 23:31:15.412422 recvfrom(16, "*0rn", 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.1rnHost: 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.1rnHos"..., 759, MSG_NOSIGNAL, NULL, 0) = 759 <0.000020> 23:31:15.435741 recvfrom(49, "HTTP/1.1 204 No Contentrn"..., 16384, 0, NULL, NULL) = 305 <0.000011> 23:31:15.440848 recvfrom(50, "HTTP/1.1 200 OKrnServer: ...."..., 16384, 0, NULL, NULL) = 822 <0.000012>
- 32. 子プロセスに根気よく実行 ● サーバの親プロセスは基本fork(spawn)するのが 役目なので、子プロセスのプロセスID を -p に指定 それでもプロセスやスレッドの忙しさにムラがあるな どの理由でなかなか動きが把握しづらい場合も多 い (うまい方法ないですかね....) おかしな動きが見つかったらラッキーくらいの気楽 な気持ちで実行するのが吉
- 33. 子プロセスに根気よく実行 www-data 6331 681 0 14:54 ? 00:00:04 /usr/sbin/apache2 -k start www-data 7260 681 0 15:23 ? 00:00:02 /usr/sbin/apache2 -k start www-data 8721 681 0 16:44 ? 00:00:02 /usr/sbin/apache2 -k start www-data 9221 681 0 17:11 ? 00:00:01 /usr/sbin/apache2 -k start www-data 11497 681 0 19:12 ? 00:00:00 /usr/sbin/apache2 -k start www-data 11500 681 0 19:12 ? 00:00:00 /usr/sbin/apache2 -k start www-data 11967 681 0 19:30 ? 00:00:00 /usr/sbin/apache2 -k start www-data 11968 681 0 19:30 ? 00:00:00 /usr/sbin/apache2 -k start www-data 15708 681 0 8月23 ? 00:00:16 /usr/sbin/apache2 -k start www-data 17784 681 0 8月24 ? 00:00:08 /usr/sbin/apache2 -k start www-data 18109 681 0 8月28 ? 00:00:06 /usr/sbin/apache2 -k start www-data 18885 681 0 10月10 ? 00:00:15 /usr/sbin/apache2 -k start www-data 20943 681 0 01:14 ? 00:00:15 /usr/sbin/apache2 -k start www-data 26089 681 0 8月28 ? 00:00:09 /usr/sbin/apache2 -k start www-data 27070 681 0 8月24 ? 00:00:09 /usr/sbin/apache2 -k start ●
- 34. 異常なシステムコールの戻り値に注目(1) ● システムコールが異常時に返す値は様々だ が、strace の出力にはエラー時に理由もついてくる ので、理由に注目。 ● No such file or directory はよくある話 ● 普段のサーバ(アプリ)の動きを把握しておこう
- 35. 異常なシステムコールの戻り値に注目(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, "foobarrn"..., 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, "hogefugarn"..., 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.458274 open("/var/log/hoge/hoge.log", O_WRONLY|O_CREAT|O_APPEND, 0666) = -1 EMFILE (Too many open files) [pid 15033] 04:39:44.458311 write(361, "hogehogern", 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, "hogehogern"..., 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.458582 open("/var/log/hoge/hoge.log", O_WRONLY|O_CREAT|O_APPEND, 0666) = -1 EMFILE (Too many open files) [pid 15033] 04:39:44.458613 write(190, "hogehogern", 5) = 5
- 36. 遅い、または詰まった動きに注目(1) ● Operation now in Progress とか <unfinished …> という類のメッセージが同じ処理でくり返されてお り、処理が進んでいないようなら要注目 ● リアルタイムで見ていると、川のように流れているト レースが一瞬詰まる瞬間が見つかることも。
- 37. 遅い、または詰まった動きに注目(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, "hogehogern", 23, 0, NULL, 0) = 23 [pid 22331] 03:55:56.483469 recvfrom(9, "+foobarrn", 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.488633 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 14 [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, "foobarrn"..., 59, 0, NULL, 0) = 59 [pid 22331] 03:55:56.489353 recvfrom(14, "hogehogern"..., 4096, 0, NULL, NULL) = 73 [pid 22331] 03:55:56.491714 socket(PF_INET, SOCK_STREAM, IPPROTO_IP) = 15 [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, "foobarn"..., 51, 0, NULL, 0) = 51 [pid 22331] 03:55:56.492177 recvfrom(15, <unfinished ...>
- 38. 遅い、または詰まった動きに注目(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 ...> [pid 1708] 14:06:19.006645 futex(0x619b60, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...> [pid 1706] 14:06:19.006662 futex(0x619b60, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
- 39. まとめ ● strace は無停止でのデバッグに重宝 動きが変なサーバを見つけたら strace してみる 変なのが見つかればラッキーくらいのつもりで ● 基本的なシステムコールを把握しよう ● よく使うオプションは限られている ● 出力を読むには少しコツがいるが、勘所をおさ えれば大丈夫
- 40. Questions?