DebianのディスクIO調査
利用しているDebianサーバーが暫時的に反応が鈍くなる現象が続いていました。ユーザー数の増加が原因だろうと、長く現象から逃避していたのですが、悔い改めて調査して改善することにしました。
状況の確認
まずは状況の確認をします。
$ vmstat 3
| r | … | us | sy | id | wa | st |
| 0 | 7 | 1 | 83 | 9 | 0 | |
| 0 | 0 | 1 | 40 | 59 | 0 | |
| 0 | 0 | 0 | 0 | 100 | 0 | |
| 0 | 0 | 0 | 0 | 100 | 0 | |
| 0 | 0 | 0 | 85 | 15 | 0 | |
| 0 | 0 | 1 | 97 | 1 | 0 | |
| 0 | 0 | 0 | 78 | 21 | 0 | |
| 0 | 0 | 1 | 84 | 15 | 0 | |
| 0 | 0 | 0 | 100 | 0 | 0 | |
| 0 | 0 | 0 | 93 | 7 | 0 |
vmstatで様子をみると処理が遅くなる周期と同じようにwa(IO待ち)が高値で張り付くので、ディスクIOが原因だろうとあたりをつけました。
vmstatで表示される項目とその意味をmanから抽出して覚書として残しておきます。
| swpd: | 仮想メモリの量。 |
| free: | 空きメモリの量。 |
| buff: | バッファに用いられているメモリの量。 |
| cache: | キャッシュに用いられているメモリの量。 |
| inact: | アクティブでないメモリの量 (-a オプション)。 |
| active: | アクティブなメモリの量 (-a オプション)。 |
| si: | ディスクからスワップインされているメモリの量 (/s)。 |
| so: | ディスクにスワップしているメモリの量 (/s)。 |
| bi: | ブロックデバイスから受け取ったブロック (blocks/s)。 |
| bo: | ブロックデバイスに送られたブロック (blocks/s)。 |
| in: | 一秒あたりの割り込み回数。クロック割り込みも含む。 |
| cs: | 一秒あたりのコンテキストスイッチの回数。 |
| us: | カーネルコード以外の実行に使用した時間 。 |
| sy: | カーネルコードの実行に使用した時間 。 |
| id: | アイドル時間。 |
| wa: | IO 待ち時間。 |
今度はvmstatに-dオプションを付けて状態を表示させてみます。表示領域の都合で、1,000を「K」、1,000,000を「M」と略している部分があります。
$ vmstat -d
| reads | writes | io | ||||||||
| total | ... | sectors | ms | total | ... | sectors | ms | cur | sec | |
| sda | 18M | 3171M | 154M | 152M | 2214M | 1166M | 0 | 636K | ||
| sdb | 303 | 15998 | 770 | 3 | 18 | 52 | 0 | 0 | ||
| dm-0 | 53K | 8424K | 781K | 23K | 294K | 3215K | 0 | 1K | ||
| ... | ||||||||||
| dm-10 | 741K | 173491K | 5379K | 33K | 308K | 3840K | 0 | 5K | ||
| dm-11 | 5105K | 1233M | 36M | 151K | 1240K | 17124K | 0 | 31K | ||
LVMを利用しているのでdm-0...の項目が連なっています。
こちらで表示される項目も確認しておきます。
| total: | 総数 |
| merged: | グループ化された (結果として 1 つの I/O となった)数 |
| sectors: | 成功したセクタ数 |
| ms: | 使用した時間 (ミリ秒) |
| total: | 総数 |
| cur: | 実行中の I/O |
| sec: | I/O に使用した時間 (秒) |
ファイルサーバーとして使っているので、全体的に読み書きが多いのですが、dm-11が突出しています。
LVMのdm-xの名前からボリュームグループとLV名を判断するには「dmsetup」コマンドを用います。
# dmsetup ls -o blkdevname LVG名-LV名 (dm-x) ...
他には「lvdisplay」を使う方法もあります。こちらは詳細なLVの情報が得られます。dm-xのxはBlock Device行の「z:x」という表記の右側の値として得られます。
dmsetupとlvdisplayは管理者権限での実行が必要です。
ディスクIOの詳細
sarコマンドを使ってディスクIOを細かく調べてみたいと思います。
sarコマンドは「sysstat」パッケージに含まれます。
sar の-bオプションの後にチェックする間隔を指定します。
$ sar -b 3
| 11時55分14秒 | tps | rtps | wtps | bread/s | bwrtn/s |
| 11時55分17秒 | 1.33 | 0.00 | 1.33 | 0.00 | 109.33 |
| 11時55分20秒 | 16.33 | 0.00 | 16.33 | 0.00 | 210.67 |
| 11時55分23秒 | 1.33 | 0.00 | 1.33 | 0.00 | 18.67 |
| 11時55分26秒 | 245.67 | 0.00 | 245.67 | 0.00 | 2288.00 |
| 11時55分29秒 | 92.00 | 0.00 | 92.00 | 0.00 | 954.67 |
| 11時55分32秒 | 0.00 | 0.00 | 0.00 | 0.00 | 0.00 |
| 11時55分35秒 | 88.33 | 0.00 | 88.33 | 0.00 | 832.00 |
| 11時55分38秒 | 0.67 | 0.00 | 0.67 | 0.00 | 112.00 |
| tps: | 物理デバイスに発行された1秒あたりの転送の総数 |
| rtps: | 上記の読み込みだけに限った数 |
| wtps: | 上記の書き込みだけに限った数 |
| bread/s: | デバイスから読み取られたデータの合計量（ブロック/秒） |
| bwrtn/s: | デバイスから書き込まれたデータの合計量（ブロック/秒） |
定期的に少なくない量の書き込みがあります。リアルタイムで動画を保存していたりするのでしょうか?
対象の絞り込み
ここまでの調査で(論理)ディスクまで調べることができました。次はアクセスが多いファイルまたはフォルダは何かというところが知りたいです。
これには以前Debianのファイルの変更監視で利用した「inotify API」を利用します。
inotifyの使い方については前回紹介しましたのでここでは簡単に設定だけ紹介します。
accessを指定してアクセス全体の監視を行いましたが、書き込みが多いのでclose_writeとして書き込みだけをチェックする方法もあると思います。
監視dirはマウントポイントを監視します。LV名からマウントポイントを得るにはdf -hとします。/dev/mapper/...と各マウントポイントとの結びつけが表示されます。
# apt install inotify-tools # inotifywait -m -q -e access -o /var/log/discaccess.log 監視dir
今回の場合は秒単位で書き込みが発生していたので、監視候補としたLVがあっていればすぐにログに出るはずですが、出ませんでした。
sarの-dオプション
もう一度sarによる監視に戻り、先ほどの-bに加えて-dオプションをデバイス毎の出力にしさらに-pオプションでdevM-n形式からわかりやすい名前に変換します。
$ sar -b -d -p 3
| DEV | tps | rkB/s | wkB/s | ... | await | ... | %util | ||
| 12時27分36秒 | sda | 35.33 | 0.00 | 224.00 | 31.96 | 12.67 | |||
| 12時27分36秒 | sdb | 0.00 | 0.00 | 0.00 | 0.00 | 0.00 | |||
| 12時27分36秒 | VMG名-VM名 | 0.00 | 0.00 | 0.00 | 0.00 | 0.00 | |||
| 12時27分36秒 | ... | ||||||||
| tps: | 1秒あたりの転送の総数 |
| rkB/s: | 1秒当たりの読み込み量(KByte) |
| wkB/s: | 1秒当たりの書き込み量(KByte) |
| areq-sz: | デバイスに発行されたリクエストの量（KByte）の平均 |
| squ-sz: | デバイスに発行されたキューの長さの平均 |
| await: | デバイスに発行されたIO要求の平均時間（ミリ秒） |
| svctm: | デバイスに発行されたIO要求の平均サービス時間(削除予定の信頼できない値) |
| %util: | デバイスの帯域幅使用率。100%に近いほどデバイス限界に近くなります。 |
リアルタイムで監視した場合、sdaのwkB/sが多いようで%utilが70を超えることもあるようです。
inoifywaitでの監視は規模が大きくなると追いきれないので、他の方法で原因を探ります。iotopというパッケージを使ってみることにします。
iotopはIO版のtopのようなコマンドで、IOの高いプロセスを順に表示するコマンドです。-aオプションを渡すか、表示中にaを押すことで集計表示に切り替わります。
テキストに出力したい場合は-bオプションを使ってリダイレクトすることで可能ですが、-aオプションによる集計はできないので-oオプションにしてIOがあるものだけに絞ります。
表記の都合上省略していますが、プロセスを起動したユーザーの表示されますので、特定のユーザーがIOを独占するような場合の特定にも利用可能です。
# iotop
| ... | DISK READ | DISK WRITE | ... | IO | COMMAND |
| 0.00B | 388.00K | 12.07% | [jbd2/sda2-8] | ||
| 0.00B | 0.00B | 10.41% | [kworker/u4:3-events_unbound] | ||
| 0.00B | 0.00B | 4.97% | [kworker/u4:1-events_unbound] | ||
| 0.00B | 0.00B | 2.81% | [kworker/u4:2+flush-8:0] | ||
| 0.00B | 48.00K | 0.66% | mysqld | ||
| 0.00B | 0.00B | 0.35% | mysqld | ||
| 0.00B | 456.00K | 0.34% | mysqld | ||
| 0.00B | 16.00K | 0.21% | mysqld | ||
| 8.00K | 15.62M | 0.20% | collectd[rrdtool queue] |
上記は-aオプションでしばらく動かしてみたところです。kworkerのIOの値も気になりますが、書き込みが多いのはcollectdということがわかりました。
collectdはいつなんのためにインストールしたかを忘れてしまったので、依存関係をチェックします。
# ldd `which collectd` linux-vdso.so.1 (0x00007ffe95f4a000) libm.so.6 => /lib/x86_64-linux-gnu/libm.so.6 (0x00007f0985d3e000) libpthread.so.0 => /lib/x86_64-linux-gnu/libpthread.so.0 (0x00007f0985d1d000) libcap.so.2 => /lib/x86_64-linux-gnu/libcap.so.2 (0x00007f0985d15000) libdl.so.2 => /lib/x86_64-linux-gnu/libdl.so.2 (0x00007f0985d10000) libc.so.6 => /lib/x86_64-linux-gnu/libc.so.6 (0x00007f0985b4f000) /lib64/ld-linux-x86-64.so.2 (0x00007f0985f08000)
なにもヒントになるようなものは見つかりませんでした。インストールの状態をaptから調べてみます。
# apt search collectd collectd/oldstable,now 5.8.1-1.3 amd64 [インストール済み、自動]
「自動」ということは、何かの依存としてインストールされたということです。
collectdはデータ統計のためのデーモンのようで、プラグインでいろいろな経路からデータを収集できるようです。
設定ファイルの/etc/collectd/collectd.confを見てみると、プラグインとしてrrdtoolが設定されていました。これは先のプロセスにも出現しているのでこのプラグインのデータを見てみます。DataDirは/var/lib/collectd/rrdという記載がありました。
rrdtoolも自動インストールのようでした。けっきょく自身の記憶を頼りにdpkg -lの一覧をあたることにしました。唯一思い当たったのが既にアンインストールしたnagiosでした。apt-file searchでcollectdやrrdtoolを調べてみるとnagiosという出力もえられたので、collectdサービスを止めることにしました。
確信がない状態でのサービス停止なので若干不安ですが、とりあえずディスクIOはもとに戻りました。
今回の調査では、次のページを参考にさせていただきました。ありがとうございました。