ボトルネック調査の基本的な手順

負荷の見極め

一般的な負荷は大きく2つに分類される。ここをまず調査する。

  • CPU負荷
  • I/O負荷

これらを見極めるために、まずロードアベレージを見ていく。

ロードアベレージ観測

ロードアベレージを見るにはいくつか方法がありますが、筆者は top を見ることが多い。

$ top

top - 10:56:23 up 23 days, 23:03,  2 users,  load average: 0.13, 0.08, 0.03
Tasks: 327 total,   1 running, 105 sleeping,   0 stopped, 151 zombie
%Cpu(s):  0.3 us,  0.4 sy,  0.0 ni, 99.3 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem :  8069384 total,  1033512 free,  1240868 used,  5795004 buff/cache
KiB Swap:  1048572 total,  1047632 free,      940 used.  6661788 avail Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
18199 ygnmhdtt  20   0  407608  28708   7484 S   1.0  0.4  11:22.06 docker-compose
30897 root      20   0  728456  27980  13556 S   1.0  0.3  57:39.16 docker-containe
30889 root      20   0 1324280  60788  35364 S   0.7  0.8  33:01.55 dockerd

一番上の load average の3つの数字(上記では0.13, 0.08, 0.03) がロードアベレージだ。

ちなみに、 top たたいた後 1 を押すとコアごとにスタッツが見られる。

ロードアベレージとは

そもそもロードアベレージとは、単位時間あたりのCPUによる実行を待っているタスクの数を示している。 基本的には上記のように0.01 ~ 0.2くらいに収まり、感覚では1を超えていると「おっ」と思う感じ。
また、障害が起きてるノードだと、10を超えるのも見たことがあります。(こうなると完全にどこかがおかしいので、直前のデプロイをノータイムでリバートからの再デプロイとかする)
左から、1分、5分、15分間の平均値を示している。

また、重要なのは、ロードアベレージが示す待ち状態のタスクとは、CPUが専有されていて実行されないタスクだけでなく、
ディスクIOを待っているタスクも含んでいる。 そのため、ロードアベレージが高いだけではCPUネックか、IOネックかは判断できない。

CPU、I/Oのいずれかがボトルネックかを探る

以下、それぞれの基本的な流れを説明する。

ロードアベレージが低い場合

まず、ロードアベレージは低い(感覚的には2以下くらい)のにシステムのスループットが上がらない場合は、サーバには負荷がかかっていない(たぶん)ため、
ソフトウェアの設定や不具合、ネットワーク(TCPコネクション数が増えていないか)、リモートホスト側に原因がないかなどを調査する ISUCONの文脈だと、インフラ側で制限かけられていてベンチマーカとアプリケーションサーバ間の帯域がサチってることもある。

例えば、80番ポートのコネクションの数を調べる場合、

$ netstat -tan | grep ':80 ' | wc -l

とか叩きます。 sysctlの設定でいじれるんですが、大体1万を超えてくると、分散化を検討する。

帯域がサチってるというのは要するにサーバーの負荷はほとんどかかっていないのに遅い、というケース。 CSSとか画像とかがネックになるケースが多い。 dstatとかでベンチ監視して、サーバー側の負荷はほとんどかかっておらず、かつネットワークIO(dstatでいうsend)も出せているのに遅い、というケースなど。 サチってることがわかったら後はCDNなりクライアント側のキャッシュなりでなんとか(要するにサーバは何も返さないという状況を作ればOK)する。

ロードアベレージが高い場合

ロードアベレージが高い場合、ここから、CPU、I/Oのいずれがボトルネックかを調査します。

CPU使用率を確認し、CPU使用率が高ければCPUネックである。 筆者はsarコマンドを使用する。

sarはsysstatパッケージに入っているコマンドであり、AmazonLinuxとかはデフォルトでは(たぶん)入ってないので、インストールが必要。 使い方としては、

$ sar -u 1 1000 # CPU使用率を、1秒ごとに1000回データを取得
Linux 4.14.8-gentoo-r1 (localhost)      04/07/2018      _x86_64_        (4 CPU)

11:16:10 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
11:16:11 AM     all      0.50      0.00      0.25      0.00      0.00     99.25
11:16:12 AM     all      0.50      0.00      0.50      0.00      0.00     99.00
$ sar -q 1 1000 # ロードアベレージ
Linux 4.14.8-gentoo-r1 (localhost)      04/07/2018      _x86_64_        (4 CPU)

11:17:47 AM   runq-sz  plist-sz   ldavg-1   ldavg-5  ldavg-15   blocked
11:17:48 AM         0       479      0.01      0.00      0.00         0
11:17:49 AM         0       479      0.01      0.00      0.00         0
11:17:50 AM         1       479      0.01      0.00      0.00         0
11:17:51 AM         0       479      0.01      0.00      0.00         0

### runq-sz: ランキューにたまっているプロセス数
### plist-sz: システム上のプロセスサイズ
### ldavg-1, 5, 15: ロードアベレージ
$ sar -r 1 1000 # メモリ使用率
Linux 4.14.8-gentoo-r1 (localhost)      04/07/2018      _x86_64_        (4 CPU)

11:19:19 AM kbmemfree kbmemused  %memused kbbuffers  kbcached  kbcommit   %commit  kbactive   kbinact   kbdirty
11:19:20 AM   1034636   7034748     87.18    942644   4511664   2357688     25.86   3444652   3020400         4
11:19:21 AM   1034512   7034872     87.18    942644   4511664   2357688     25.86   3444652   3020400         4
11:19:22 AM   1034512   7034872     87.18    942644   4511664   2357688     25.86   3444652   3020400         4
$ sar -W 1 1000 # スワップ状況
Linux 4.14.8-gentoo-r1 (localhost)      04/07/2018      _x86_64_        (4 CPU)

11:21:31 AM  pswpin/s pswpout/s
11:21:32 AM      0.00      0.00
11:21:33 AM      0.00      0.00
11:21:34 AM      0.00      0.00

### pswpin/s: 1秒間にスワップインしているページ数
### pswpout/s: 1秒間にスワップアウトしているページ数
sar -P ALL 1 1000 # コアごとのCPU使用率
Linux 4.14.8-gentoo-r1 (localhost)      04/07/2018      _x86_64_        (4 CPU)

11:25:36 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
11:25:37 AM     all      0.25      0.00      0.25      0.00      0.00     99.50
11:25:37 AM       0      0.00      0.00      1.00      0.00      0.00     99.00
11:25:37 AM       1      1.00      0.00      0.00      0.00      0.00     99.00
11:25:37 AM       2      1.00      0.00      0.00      0.00      0.00     99.00
11:25:37 AM       3      0.00      0.00      0.00      0.00      0.00    100.00

11:25:37 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
11:25:38 AM     all      0.50      0.00      0.25      0.00      0.00     99.25
11:25:38 AM       0      0.00      0.00      0.00      0.00      0.00    100.00
11:25:38 AM       1      0.00      0.00      0.00      0.00      0.00    100.00
11:25:38 AM       2      1.01      0.00      1.01      0.00      0.00     97.98
11:25:38 AM       3      0.00      0.00      0.00      0.00      0.00    100.00

11:25:38 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
11:25:39 AM     all      0.25      0.00      0.50      0.00      0.00     99.25
11:25:39 AM       0      0.00      0.00      0.00      0.00      0.00    100.00
11:25:39 AM       1      0.00      0.00      0.00      0.00      0.00    100.00
11:25:39 AM       2      1.01      0.00      0.00      0.00      0.00     98.99
11:25:39 AM       3      0.00      0.00      1.00      0.00      0.00     99.00

11:25:39 AM     CPU     %user     %nice   %system   %iowait    %steal     %idle
11:25:40 AM     all      0.50      0.00      0.25      0.00      0.00     99.25
11:25:40 AM       0      0.00      0.00      1.00      0.00      0.00     99.00
11:25:40 AM       1      0.99      0.00      0.99      0.00      0.00     98.02
11:25:40 AM       2      1.00      0.00      0.00      0.00      0.00     99.00
11:25:40 AM       3      1.01      0.00      0.00      0.00      0.00     98.99

スワップについて

swapがあるのかどうかは swapon で確認する。

$ swapon -v
NAME      TYPE       SIZE USED PRIO
/dev/sda5 partition 1024M 940K   -2

/dev/sda5がスワップになっている。

CPU負荷が高い場合

CPU負荷が高い場合、以下の流れで探っていく。

  • psで見えるプロセスの状態やCPU使用時間などを見ながら、原因となっているプロセスを特定する。
  • プロセスを特定したら、straceでシステムコールをトレース、oprofileでプロファイリングをして、ボトルネック箇所を絞り込む。
  • goアプリだったらpprof 。ほかはわからない

IO負荷が高い場合

CPU負荷が高くない場合はIO負荷を疑う。
IO負荷の場合、プログラムからの入出力が多いか、
スワップが発生してディスクアクセスが発生しているかのいずれかである場合がほとんど。
上記の sar -W でスワップの発生状況を確認する。

スワップが発生している場合:

  • psで極端にメモリを食っているプロセスを特定。
  • プログラムの不具合であればプログラムを改善。
  • 搭載メモリが不足している場合はメモリ増設で対応。メモリ増設できない場合は分散。

スワップが発生していない場合:
キャッシュに必要なメモリが不足しているケースが考えられる。

  • メモリが増やせる場合は増設。
  • それ以外では、分散やキャッシュサーバの導入などを検討。また、プログラム改善でI/O頻度を軽減する。

その他

以下のようなコマンドもよく使う。

  • vmstat
$ vmstat 1 1000
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 1  0    940 1033456 942644 4852684    0    0     5    19    1    2  2  0 98  0  0
 0  0    940 1033628 942644 4852688    0    0     0     0  278  644  1  0 99  0  0
 0  0    940 1033596 942644 4852688    0    0     0     0  267  635  1  0 99  0  0
  • iftop … ネットワークのI/Oプロファイリング
  • iotop … プロセスごとのDISK I/Oが見られる
  • dstat … いろいろまとめて見られる
  • gotop … きれいに見られる