パフォーマンス問題でLinuxサーバーにログインしたとして、最初の1分で何を調べますか？
Netflixには、多数のEC2 Linuxからなるクラウドがあり、そのパフォーマンスを監視したり調査したりするための数々のパフォーマンス分析ツールがあります。その中には、クラウド全体にわたる監視を行うAtlasや、オンデマンドにインスタンスの分析を行うVectorがあります。これらのツールは多くの問題を解決する手助けをしてくれますが、各インスタンスにログインし、標準的なLinuxパフォーマンスツールを実行する必要がある場合もあります。
この記事では、すぐ使えるはずの標準的Linuxツールを使いコマンドラインにおいて、最適化されたパフォーマンス調査をする際の最初の60秒を、Netflixパフォーマンスエンジニアリングチームがお見せしようと思います。
最初の60秒 : 概要
60秒で、以下の10のコマンドを実行することで、システムリソースの使用状況と実行中のプロセスに関して高レベルな当たりをつけることができます。まず簡単に見分けがつくエラーと飽和状態のメトリクスを見て、それからリソースの使用状況を見ます。飽和状態とは、処理できる量を超えて負荷がかかっているリソースで、リクエストキューの長さや待ち時間の長さのどちらかからわかります。
uptime
dmesg | tail
vmstat 1
mpstat -P ALL 1
pidstat 1
iostat -xz 1
free -m
sar -n DEV 1
sar -n TCP,ETCP 1
top
いくつかのコマンドはsysstatパッケージがインストールされている必要があります。これらのコマンドが明らかにしてくれるメトリクスは、パフォーマンスボトルネックを特定する方法論であるUSEメソッドの一部を満たすのに役立ちます。これには、あらゆるリソース(CPU、メモリ、ディスクなど)の使用率や飽和状態やエラーメトリクスを調べることが含まれます。また、いつリソースを確認し、解放したかにも注意を払いましょう。除外するプロセスにより、調べるべき範囲を狭め、調査における次の手を示唆してくれます。
以降の節では、本番のシステムでの例を合わせつつこれらのコマンドをまとめます。ツールの詳しい情報は、manページを参照してください。
1. uptime
$ uptime
23:51:26 up 21:31, 1 user, load average: 30.02, 26.43, 19.02
実行を待っているタスク(プロセス)の数を表す、ロードアベレージを素早く確認する方法です。Linuxシステムでは、CPUでの実行を待っているプロセスの数の他に、割り込み不可能なI/O(通常はディスクI/O)でブロックされているプロセスを含んでいます。これでリソースの負荷(あるいは要求具合)の高レベルな概要を知ることができますが、他のツールを使わずに正しく理解することはできません。素早く確認することだけに限られます。
3つの数字は、1分間、5分間、15分間の指数移動平均です。これらの数字は、負荷が時間経過とともにどのように変化したかの情報を教えてくれます。例えば、問題のあるサーバのチェックを依頼され、1分の値が15分の値よりもずっと小さくなっていたら、ログインしたのは手遅れで、問題を見逃してしまっているでしょう。
上の例では、ロードアベレージは直近増えていて、15分の値は19なのに対して1分の値は30を超えています。値がこのように大きいのは何か色々な事が起きている証拠です。おそらくCPU処理の要求か何かでしょう。この記事の3と4に出てくるvmstatかmpstatで確認しましょう。
2. dmesg | tail
$ dmesg | tail
[1880957.563150] perl invoked oom-killer: gfp_mask=0x280da, order=0, oom_score_adj=0
[...]
[1880957.563400] Out of memory: Kill process 18694 (perl) score 246 or sacrifice child
[1880957.563408] Killed process 18694 (perl) total-vm:1972392kB, anon-rss:1953348kB, file-rss:0kB
[2320864.954447] TCP: Possible SYN flooding on port 7001. Dropping request. Check SNMP counters.
これで、システムメッセージの最後の10行に何かあれば確認します。パフォーマンス問題につながりかねないエラーを見つけましょう。上の例では、oom-killerとTCPのリクエストのドロップが含まれています。
この手順を忘れないように！dmesgはいつも確認する価値のある情報が含まれています。
3. vmstat 1
$ vmstat 1
procs ---------memory---------- ---swap-- -----io---- -system-- ------cpu-----
r b swpd free buff cache si so bi bo in cs us sy id wa st
34 0 0 200889792 73708 591828 0 0 0 5 6 10 96 1 3 0 0
32 0 0 200889920 73708 591860 0 0 0 592 13284 4282 98 1 1 0 0
32 0 0 200890112 73708 591860 0 0 0 0 9501 2154 99 1 0 0 0
32 0 0 200889568 73712 591856 0 0 0 48 11900 2459 99 0 0 0 0
32 0 0 200890208 73712 591860 0 0 0 0 15898 4840 98 1 1 0 0
^C
仮想メモリの統計を簡単に表示するツールとして、vmstat(8)は広く利用可能です(最初は数十年前にBSD向けに作られたものです)。各行に、サーバの鍵となる統計情報のサマリーを表示します。
1秒のサマリーを表示するために、vmstatには1という引数を渡して実行します。(このバージョンのvmstatでは)出力の最初の1行は、前の1秒の情報ではなく起動からの平均を表示します。どの列がどれかを覚えたかったり忘れてしまったのでなければ、最初の行は読み飛ばしましょう。
見るべき列は以下の通りです。
r : CPUで実行中および順番を待っているプロセスの数。これはI/Oを含んでいないので、CPUの飽和状態を見るのに、ロードアベレージよりも良いシグナルになります。言い換えると、"r"の値がCPU数よりも多ければ飽和状態ということです。
free : キロバイトでの空きメモリー量。数えられないぐらいの桁数が表示されていたら、十分なメモリーがあります。7番目に出てくる
free -mコマンドは、空きメモリのより詳しい説明を表示してくれます。si, so : スワップインとスワップアウト。ゼロでない値があれば、メモリ不足。
us, sy, id, wa, st : CPU時間の内訳で、すべてのCPUに対する平均値。それぞれ、ユーザ時間、システム(カーネル)時間、アイドル時間、I/O待ち時間、stealされた時間(他のゲストマシンや、Xenの場合ゲストの分離されたドライバードメインによるsteal)。
CPU時間の内訳で、userとsystem時間を足すことでCPUがビジーかどうか確認できるでしょう。I/O待ちが一定の数値を示しているならディスクがボトルネックです。この時、タスクはディスクI/O待ちでブロックされてしまうため、CPUはアイドル状態になってしまっています。従って、I/O待ちはCPUアイドル時間の別の形と考えられ、なぜアイドルなのかを調べる手がかりになり得ます。
システム時間は、I/O処理に必要です。20%を超えるような高いシステム時間は、詳しく調べる必要があると言えるでしょう。おそらくカーネルがI/Oを効率よく処理できていない状態です。
上の例では、CPU時間はほとんどユーザレベルになっており、つまりアプリケーションレベルが使用していることを示しています。CPUは平均90%以上使用されています。これは必ずしも問題とは言えず、「r」列で飽和状態の程度を調べましょう。
4. mpstat -P ALL 1
$ mpstat -P ALL 1
Linux 3.13.0-49-generic (titanclusters-xxxxx) 07/14/2015 _x86_64_ (32 CPU)
07:38:49 PM CPU %usr %nice %sys %iowait %irq %soft %steal %guest %gnice %idle
07:38:50 PM all 98.47 0.00 0.75 0.00 0.00 0.00 0.00 0.00 0.00 0.78
07:38:50 PM 0 96.04 0.00 2.97 0.00 0.00 0.00 0.00 0.00 0.00 0.99
07:38:50 PM 1 97.00 0.00 1.00 0.00 0.00 0.00 0.00 0.00 0.00 2.00
07:38:50 PM 2 98.00 0.00 1.00 0.00 0.00 0.00 0.00 0.00 0.00 1.00
07:38:50 PM 3 96.97 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 3.03
[...]
このコマンドは、(CPU間の)バランスの悪さを確認するために使える、CPUごとのCPU時間の内訳を表示します。ひとつのCPUだけが忙しいのは、シングルスレッドアプリケーションが動いている証拠になり得ます。
5. pidstat 1
$ pidstat 1
Linux 3.13.0-49-generic (titanclusters-xxxxx) 07/14/2015 _x86_64_ (32 CPU)
07:41:02 PM UID PID %usr %system %guest %CPU CPU Command
07:41:03 PM 0 9 0.00 0.94 0.00 0.94 1 rcuos/0
07:41:03 PM 0 4214 5.66 5.66 0.00 11.32 15 mesos-slave
07:41:03 PM 0 4354 0.94 0.94 0.00 1.89 8 java
07:41:03 PM 0 6521 1596.23 1.89 0.00 1598.11 27 java
07:41:03 PM 0 6564 1571.70 7.55 0.00 1579.25 28 java
07:41:03 PM 60004 60154 0.94 4.72 0.00 5.66 9 pidstat
07:41:03 PM UID PID %usr %system %guest %CPU CPU Command
07:41:04 PM 0 4214 6.00 2.00 0.00 8.00 15 mesos-slave
07:41:04 PM 0 6521 1590.00 1.00 0.00 1591.00 27 java
07:41:04 PM 0 6564 1573.00 10.00 0.00 1583.00 28 java
07:41:04 PM 108 6718 1.00 0.00 0.00 1.00 0 snmp-pass
07:41:04 PM 60004 60154 1.00 4.00 0.00 5.00 9 pidstat
^C
pidstatは、topのプロセスごとの概要とも言えるものですが、スクリーンをクリアする代わりに連続して概要を表示します。これは、時系列でのパターンを見るのに便利で、見たものを調査の記録にとっておく(コピペ)のにもよいでしょう。
上の例では、2つのjavaプロセスがCPUを消費している原因だとわかります。%CPU列は全CPUに対する使用率ですが、1591%という表示からjavaプロセスがほぼ16CPU分を使用していると分かります。
6. iostat -xz 1
$ iostat -xz 1
Linux 3.13.0-49-generic (titanclusters-xxxxx) 07/14/2015 _x86_64_ (32 CPU)
avg-cpu: %user %nice %system %iowait %steal %idle
73.96 0.00 3.73 0.03 0.06 22.21
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
xvda 0.00 0.23 0.21 0.18 4.52 2.08 34.37 0.00 9.98 13.80 5.42 2.44 0.09
xvdb 0.01 0.00 1.02 8.94 127.97 598.53 145.79 0.00 0.43 1.78 0.28 0.25 0.25
xvdc 0.01 0.00 1.02 8.86 127.79 595.94 146.50 0.00 0.45 1.82 0.30 0.27 0.26
dm-0 0.00 0.00 0.69 2.32 10.47 31.69 28.01 0.01 3.23 0.71 3.98 0.13 0.04
dm-1 0.00 0.00 0.00 0.94 0.01 3.78 8.00 0.33 345.84 0.04 346.81 0.01 0.00
dm-2 0.00 0.00 0.09 0.07 1.35 0.36 22.50 0.00 2.55 0.23 5.62 1.78 0.03
[...]
^C
ブロックデバイス(ディスク)に適用されるワークロードと、その結果のパフォーマンスの両方を理解出来る素晴らしいツールです。見方は以下の通り。
- r/s, w/s, rkB/s, wkB/s : 秒間にデバイスに送られた読み出し回数、書き込み回数、読み出しキロバイト、書き込みキロバイトを表します。ワークロードの特徴をつかむのに使いましょう。パフォーマンスの問題はたいていの場合、単に過剰な負荷がかけられていることが原因です。
await : I/Oの平均時間のミリ秒表示。これは、アプリケーションが待たされた時間で、キューに入っていた時間と実際のサービス時間の両方を含んでいます。期待した平均時間より長い場合、デバイスが飽和状態か、デバイス自体に問題がある可能性があります。
avgqu-sz : デバイスに対して発行されたリクエストの平均数。(複数のバックエンドディスクの前に立つ仮想デバイスは特に、デバイスはリクエストを通常は並行に処理しますが)1より大きい値は、飽和状態を表します。
%util : デバイスの使用率。これは、実際にはビジーな割合で、デバイスが仕事をした時間を秒ごとに出したものです。デバイスにもよりますが、一般的に60%より大きい値はパフォーマンスの劣化(awaitにも表れます)につながります。100％に近い値は通常、飽和状態を意味します。
ストレージデバイスがたくさんのバックエンドディスクを持つ論理ディスクデバイスの場合、使用率が100%ということは、なんらかのI/Oが100%の時間処理され続けているということである一方で、バックエンドディスクは飽和状態からは程遠い可能性が高く、もっと多くの処理が可能なはずです。
頭にとどめておきたいのは、ディスクI/Oのパフォーマンスが悪いことは、必ずしもアプリケーションの問題になるわけではないということです。I/Oを非同期に実行するために、多くのテクニックがよく使われるので、アプリケーションはブロックされず、レイテンシも直接は影響してこないのです(例、読み出しには先読み、書き込みにはバッファリング)。
7. free -m
$ free -m
total used free shared buffers cached
Mem: 245998 24545 221453 83 59 541
-/+ buffers/cache: 23944 222053
Swap: 0 0 0
一番右の2つの列は以下を表しています。
- buffers : ブロックデバイスのI/Oに使われるバッファーキャッシュ
- cached : ファイルシステムによって使われるページキャッシュ
ディスクI/Oが高負荷になり(iostatで確認しましょう)パフォーマンスが悪化する可能性につながりかねないので、これらの値がゼロに近い値でないかを確認しておきたいところです。上の例では多くの容量がそれぞれありますので問題ないようです。
“-/+ buffers/cache”は、使用中あるいは空きメモリを(buffersとcachedを足し引きすることで)表す分かりやすい値を表示します。Linuxは空きメモリをキャッシュに使用しますが、アプリケーションがメモリを要求した時にはすぐにそれを回収します。従って、cachedなメモリは同じ行にある空きメモリの列の値に含まれているべきだということになります。この分かりにくさについてはlinuxatemyramというウェブサイトまであるぐらいです。
私たちもいくつかのサービスで使っていますが、ZFS on Linuxを使っていると、さらに混乱しやすくなります。ZFSは独自のファイルシステムキャッシュを持っており、free -mの列に正しく反映されないためです。必要ならZFSのキャッシュから使うことができるメモリがある時でも、空きメモリが不足していると表示されてしまうのです。
8. sar -n DEV 1
$ sar -n DEV 1
Linux 3.13.0-49-generic (titanclusters-xxxxx) 07/14/2015 _x86_64_ (32 CPU)
12:16:48 AM IFACE rxpck/s txpck/s rxkB/s txkB/s rxcmp/s txcmp/s rxmcst/s %ifutil
12:16:49 AM eth0 18763.00 5032.00 20686.42 478.30 0.00 0.00 0.00 0.00
12:16:49 AM lo 14.00 14.00 1.36 1.36 0.00 0.00 0.00 0.00
12:16:49 AM docker0 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
12:16:49 AM IFACE rxpck/s txpck/s rxkB/s txkB/s rxcmp/s txcmp/s rxmcst/s %ifutil
12:16:50 AM eth0 19763.00 5101.00 21999.10 482.56 0.00 0.00 0.00 0.00
12:16:50 AM lo 20.00 20.00 3.25 3.25 0.00 0.00 0.00 0.00
12:16:50 AM docker0 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00
^C
このツールで、ワークロードの目安になるネットワークインターフェースのスループットであるrxkB/sとtxkB/sを調べましょう。また、なんらかの制限に達していないかどうかも確認しましょう。上の例では、eth0が22Mbytes/s、つまり176Mbits/secを受信しています(1Gbit/secの制限を十分下回っています)。
このバージョンでは、デバイスの使用率(全二重での上り下り両方での最大値)として%ifutilも表示されていて、これはBrendanのnicstatツールでの計測のためにも使います。ただし、nicstatと同じく、なかなか正しい値を示してはくれず、上の例(0.00)のようにちゃんと動いていないように見える場合が多いようです。
9. sar -n TCP,ETCP 1
$ sar -n TCP,ETCP 1
Linux 3.13.0-49-generic (titanclusters-xxxxx) 07/14/2015 _x86_64_ (32 CPU)
12:17:19 AM active/s passive/s iseg/s oseg/s
12:17:20 AM 1.00 0.00 10233.00 18846.00
12:17:19 AM atmptf/s estres/s retrans/s isegerr/s orsts/s
12:17:20 AM 0.00 0.00 0.00 0.00 0.00
12:17:20 AM active/s passive/s iseg/s oseg/s
12:17:21 AM 1.00 0.00 8359.00 6039.00
12:17:20 AM atmptf/s estres/s retrans/s isegerr/s orsts/s
12:17:21 AM 0.00 0.00 0.00 0.00 0.00
^C
これは、いくつかの重要なTCP関連メトリクスの概要です。以下を含んでいます。
- active/s : 1秒あたりのローカルから接続を開始したTCPコネクション数(例、
connect()による接続) - passive/s : 1秒あたりのリモートから接続を開始したTCPコネクション数(例、
accept()による接続) - retrans/s : 1秒あたりのTCP再送数
active/sとpassive/sの数は、それぞれ新しく受け入れたコネクション数と新しく下流に向けて張ったコネクション数で、サーバーの負荷をおおまかに把握するのに便利です。activeを外向き、passiveを内向きと考えるのに便利ですが、厳密に正しいとは言えません(ローカルホストからローカルホストへのコネクションなどを考慮する必要があるなど)。
再送はネットワークあるいはサーバーの問題のサインです。ネットワークの信頼性が低い(例、パブリックなインターネット)か、サーバーが過負荷でパケットをドロップしているかでしょう。上の例では、1秒に1 TCPコネクションしか生成されていません。
10. top
$ top
top - 00:15:40 up 21:56, 1 user, load average: 31.09, 29.87, 29.92
Tasks: 871 total, 1 running, 868 sleeping, 0 stopped, 2 zombie
%Cpu(s): 96.8 us, 0.4 sy, 0.0 ni, 2.7 id, 0.1 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem: 25190241+total, 24921688 used, 22698073+free, 60448 buffers
KiB Swap: 0 total, 0 used, 0 free. 554208 cached Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
20248 root 20 0 0.227t 0.012t 18748 S 3090 5.2 29812:58 java
4213 root 20 0 2722544 64640 44232 S 23.5 0.0 233:35.37 mesos-slave
66128 titancl+ 20 0 24344 2332 1172 R 1.0 0.0 0:00.07 top
5235 root 20 0 38.227g 547004 49996 S 0.7 0.2 2:02.74 java
4299 root 20 0 20.015g 2.682g 16836 S 0.3 1.1 33:14.42 java
1 root 20 0 33620 2920 1496 S 0.0 0.0 0:03.82 init
2 root 20 0 0 0 0 S 0.0 0.0 0:00.02 kthreadd
3 root 20 0 0 0 0 S 0.0 0.0 0:05.35 ksoftirqd/0
5 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 kworker/0:0H
6 root 20 0 0 0 0 S 0.0 0.0 0:06.94 kworker/u256:0
8 root 20 0 0 0 0 S 0.0 0.0 2:38.05 rcu_sched
topコマンドには、これより前に見てきたメトリクスの多くが含まれています。負荷が変わりやすいことを示してくれるここまで見てきたコマンドと違って、ざっくりと確認したいときには便利でしょう。
topの良くないところとしては、時間を追って表れるパターンをつかみにくいことで、これらは連続して出力を出してくれるvmstatやpidstatなどの方がよりはっきりと分かります。間欠的に現れる現象についても、出力を素早く停止(Ctrl-Sで一時停止、Ctrl-Sで再開)できないとスクリーンがクリアされて消えてしまいます。
さらなる分析を
さらに深く調べるのに使えるコマンドや方法がたくさんあります。可観測性、ベンチマーク、チューニング、静的なパフォーマンスチューニング、プロファイル、トレースに関する40以上のコマンドを取り上げたVelocity 2015でのBrendanのLinux Performance Tools tutorialを見てください。
ウェブスケールでシステムの信頼性やパフォーマンス問題を追い求めるのは、私たちの情熱をかけていることのひとつです。これらの問題に挑戦して私たちの仲間入りをしたい方がいれば、ぜひ応募してください！