一歩踏み込んだnginxのプロファイリングをする - ps aux

ISHOCON2で惨敗して、悔しくてたまらなくてhttp2やnginxのことについてずっと調べたので、調査記録として残しておく。

serinuntius.hatenablog.jp

一番手軽で万能な「strace」
- 使い方
  - ざっくりと集計してボトルネックを探す
  - 集計結果を元にあたりをつけて調査する
出すのは面倒だけどわかりやすい「FlameGraph」
2つの調査結果から考えられる対策
まとめ
参考

一番手軽で万能な「strace」

straceとはprocessに直接アタッチして、システムコールを調査するためのコマンドです。

インストールも簡単で、使うのも簡単です。しかも、どんなツールにも使うことができます。

しかし、読み解くのは難しいです。(個人的な感想です。)

使い方

ざっくりと集計してボトルネックを探す

まず、調査対象のpidが必要なので、 ps aux|grep nginx とかで nginxのpidを調べます。

ubuntu@ip-172-31-21-29:~$ ps aux|grep nginx
root     20904  0.0  0.0  42976   852 ?        Ss   04:22   0:00 nginx: master process /usr/sbin/nginx -g daemon on; master_process on;
root     20905  0.0  0.1  48424  6848 ?        S    04:22   0:00 nginx: worker process
root     20906  0.0  0.0  47752  3664 ?        S    04:22   0:00 nginx: worker process
ubuntu   22510  0.0  0.0  13136   972 pts/0    S+   11:54   0:00 grep --color=auto nginx

masterプロセスではなく、worker processのpidをメモしておきます。この例だと、20905か20906ですね。どちらでも良いです。

strace -c -S time -p 20905

オプションの意味は

-c で集計
-S で集計結果を何でソートするか(今回はtime)
-p pid

だと理解しています。

この状態で、ベンチマーカーを回します。*1

ベンチマーカーを回して、もう良いかな〜というタイミングで ctrl-c で止めます。すると、こんな感じで集計結果が見れます。 f:id:serinuntius:20180826210931p:plain

readを占める割合が一番多いですね。あと、エラーがめっちゃ出ているのも気になります。

集計結果を元にあたりをつけて調査する

先程の集計結果で、 read を占める割合が一番多かったので、 read のシステムコールだけ追ってみます。

sudo strace -T -s 1024 -e read -p 22773 -k -o /tmp/strace.read.stack

オプションの意味は次のような感じだと理解しています。

-T 時間を出す
-s 1024 (デフォルトだと、1行の長さが省略されてしまうので、適当に長くする)
-e read (システムコールを絞り込む。)
-p pid
-k (スタックトレースを出す)
-o /tmp/strace.read.stack (ファイルに出力する)

このログを見ていると、

read(10, "\26\3\1\0\237\1\0\0\233\3\3\312\323\257.\224\3\2750C.\374os\302\343\16\310\7\214\2104\341\332\252\7\204\362\355#,v)\0\0 \300/\3000\300+\300,\314\250\314\251\300\23\300\
t\300\24\300\n\0\234\0\235\0/\0005\300\22\0\n\1\0\0R3t\0\0\0\5\0\5\1\0\0\0\0\0\n\0\n\0\10\0\35\0\27\0\30\0\31\0\v\0\2\1\0\0\r\0\22\0\20\4\1\4\3\5\1\5\3\6\1\6\3\2\1\2\3\377\1\0\1\
0\0\20\0\16\0\f\2h2\10http/1.1\0\22\0\0", 16709) = 164 <0.000035>
 > /lib/x86_64-linux-gnu/libpthread-2.27.so(read+0xe) [0x1134e]
 > /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1(BIO_sock_should_retry+0x5e) [0xa0a2e]
 > /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1(BIO_read+0x63) [0x9b613]
 > /usr/lib/x86_64-linux-gnu/libssl.so.1.1(SSL_rstate_string+0x148) [0x1c3e8]
 > /usr/lib/x86_64-linux-gnu/libssl.so.1.1(SSL_rstate_string+0x3e67) [0x20107]
 > /usr/lib/x86_64-linux-gnu/libssl.so.1.1(SSL_rstate_string+0x17d3) [0x1da73]
 > /usr/lib/x86_64-linux-gnu/libssl.so.1.1(SSL_in_before+0x850d) [0x3f40d]
 > /usr/lib/x86_64-linux-gnu/libssl.so.1.1(SSL_in_before+0x6aa) [0x375aa]
 > /usr/lib/x86_64-linux-gnu/libssl.so.1.1(SSL_do_handshake+0x41) [0x2f901]
 > /usr/sbin/nginx(ngx_ssl_handshake+0x3d) [0x5418d]
 > /usr/sbin/nginx(ngx_http_process_request+0x1364) [0x6a024]
 > /usr/sbin/nginx(ngx_os_specific_status+0x56c) [0x4f89c]
 > /usr/sbin/nginx(ngx_process_events_and_timers+0x54) [0x44934]
 > /usr/sbin/nginx(ngx_dlerror+0xe85) [0x4d7e5]
 > /usr/sbin/nginx(ngx_spawn_process+0x1a1) [0x4bc11]
 > /usr/sbin/nginx(ngx_dlerror+0x560) [0x4cec0]
 > /usr/sbin/nginx(ngx_master_process_cycle+0x1ce) [0x4e58e]
 > /usr/sbin/nginx(main+0xab6) [0x22506]
 > /lib/x86_64-linux-gnu/libc-2.27.so(__libc_start_main+0xe7) [0x21b97]
 > /usr/sbin/nginx(_start+0x2a) [0x226fa]
read(10, 0x56235cb4d0a3, 16709)         = -1 EAGAIN (Resource temporarily unavailable) <0.000029>
 > /lib/x86_64-linux-gnu/libpthread-2.27.so(read+0xe) [0x1134e]
 > /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1(BIO_sock_should_retry+0x5e) [0xa0a2e]
 > /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1(BIO_read+0x63) [0x9b613]
 > /usr/lib/x86_64-linux-gnu/libssl.so.1.1(SSL_rstate_string+0x148) [0x1c3e8]
 > /usr/lib/x86_64-linux-gnu/libssl.so.1.1(SSL_rstate_string+0x3e67) [0x20107]
 > /usr/lib/x86_64-linux-gnu/libssl.so.1.1(SSL_rstate_string+0x17d3) [0x1da73]
 > /usr/lib/x86_64-linux-gnu/libssl.so.1.1(SSL_in_before+0x850d) [0x3f40d]
 > /usr/lib/x86_64-linux-gnu/libssl.so.1.1(SSL_in_before+0x6aa) [0x375aa]
 > /usr/lib/x86_64-linux-gnu/libssl.so.1.1(SSL_do_handshake+0x41) [0x2f901]
 > /usr/sbin/nginx(ngx_ssl_handshake+0x3d) [0x5418d]
 > /usr/sbin/nginx(ngx_http_process_request+0x1364) [0x6a024]
 > /usr/sbin/nginx(ngx_os_specific_status+0x56c) [0x4f89c]
 > /usr/sbin/nginx(ngx_process_events_and_timers+0x54) [0x44934]
 > /usr/sbin/nginx(ngx_dlerror+0xe85) [0x4d7e5]
 > /usr/sbin/nginx(ngx_spawn_process+0x1a1) [0x4bc11]
 > /usr/sbin/nginx(ngx_dlerror+0x560) [0x4cec0]
 > /usr/sbin/nginx(ngx_master_process_cycle+0x1ce) [0x4e58e]
 > /usr/sbin/nginx(main+0xab6) [0x22506]
 > /lib/x86_64-linux-gnu/libc-2.27.so(__libc_start_main+0xe7) [0x21b97]
 > /usr/sbin/nginx(_start+0x2a) [0x226fa]

まぁ、本当はもっとあるんですが、だいたいこれが並んでいます。

これ見て気づくのは、libssl.so とか libcrypto.so とか、重そうなやつが並んでますね〜。

つまりこれは TLSのハンドシェイクが負荷となっているわけです。(たぶん)

なのでいい感じの対策を考えなければなりません。

対策は、後ろでまとめます。

出すのは面倒だけどわかりやすい「FlameGraph」

straceとは別のアプローチとして、FlameGraphを出してみるというのがある。

nginx profilingでググると、一番上にOpenRestyの記事がヒットする。

The most useful tools are

C-land on-CPU Flame Graph tool: https://github.com/openresty/nginx-systemtap-toolkit#sample-bt

C-land off-CPU Flame Graph tool: https://github.com/openresty/nginx-systemtap-toolkit#sample-bt-off-cpu

Lua-land on-CPU Flame Graph tool: https://github.com/openresty/stapxx#lj-lua-stacks

そこで紹介されているのが、 openresty/nginx-systemtap-toolkit というやつです。

今回はそれを使ってみます。

インストール方法

sudo apt-get install -y systemtap gcc
git clone https://github.com/openresty/nginx-systemtap-toolkit
git clone https://github.com/brendangregg/FlameGraph

使い方

まず、 .bt っていうのを生成するらしい

cd nginx-systemtap-toolkit
sudo ./sample-bt -p 17084 -t 10 -u > /tmp/a.bt

オプションの意味は、

-p nginxのpid
-t 10(時間、僕の環境だと長くするとエラーでちゃう)

次に、さっきの .bt から .cbt を生成する。その、.cbt から .svg を生成する。

# cloneしたFlameGraphのリポジトリに移動する。
cd ../FlameGraph

# btからcbtを生成する
./stackcollapse-stap.pl /tmp/a.bt > /tmp/a.cbt

# cbtからsvgを生成する
./flamegraph.pl /tmp/a.cbt > /tmp/a.svg

あとは、これをscpとかでローカルに持ってくるなりして、ブラウザなりで開いてみるといい感じのFlameGraphが表示されるはずです。

読み解き方は、僕の雑な記事や、Deeeeetさんの神記事GolangでFlame Graphを描くを読むと良いかもしれません。