DISK I/Oが発生している要因

Question

前提・実現したいこと

さくらVPSを使用しております。
DISK I/Oが発生している要因を調査したいと考えています。
時々一時的に急激に上がったりしています。
なお特にアプリは動かしてはいません。

dstat -taf で、IO負荷を確認しています。
dsk/vdaで時々、writに値が発生しています。

これは書き込みが発生しているという認識でよろしいでしょうか。
その書き込みはどうやって発生しているか確認する方法はありますでしょうか。

ご教授のほどどうかよろしくお願いします。

調査したい箇所

一時的に増加している。

調査例1

  date/time   |usr sys idl wai hiq siq:usr sys idl wai hiq siq| read  writ| recv  send|  in   out | int   csw 
08-04 19:52:10|  0   0 100   0   0   0:  0   0 100   0   0   0|   0     0 |1594B  442B|   0     0 |  57    27 
08-04 19:52:11|  0   0 100   0   0   0:  0   0 100   0   0   0|   0     0 |1774B  442B|   0     0 |  48    19 
08-04 19:52:12|  0   0 100   0   0   0:  0   0 100   0   0   0|   0     0 |1354B  442B|   0     0 |  58    19 
08-04 19:52:13|  1   0  99   0   0   0:  0   0 100   0   0   0|   0     0 |1834B  442B|   0     0 |  51    19 
08-04 19:52:14|  0   0 100   0   0   0:  0   0 100   0   0   0|   0     0 |1774B  442B|   0     0 |  45    17 
08-04 19:52:15|  0   0 100   0   0   0:  0   0 100   0   0   0|   0  4096B|1594B  442B|   0     0 |  57    28 
08-04 19:52:16|  0   0 100   0   0   0:  0   0 100   0   0   0|   0     0 |1714B  442B|   0     0 |  52    17 

調査例2

上記に対しswapを確認

vmstat -t 2

procs -----------memory---------- ---swap-- -----io---- --system-- -----cpu------ ---timestamp---
r b swpd free buff cache si so bi bo in cs us sy id wa st
0 0 0 264692 190432 363308 0 0 0 0 3 2 0 0 100 0 0 2019-04-08 20:56:48 JST
0 0 0 264668 190432 363308 0 0 0 0 49 20 0 0 100 0 0 2019-04-08 20:56:50 JST
0 0 0 264668 190432 363308 0 0 0 0 49 17 0 0 100 0 0 2019-04-08 20:56:52 JST
0 0 0 264668 190432 363308 0 0 0 44 45 20 0 0 100 0 0 2019-04-08 20:56:54 JST
0 0 0 264668 190432 363308 0 0 0 0 45 17 0 0 100 0 0

調査例3

sarコマンド
proc/s.... 1秒あたりの生成されたプロセス数
cswch/s... 1秒あたりのコンテキストスイッチ回数

tps.............. 1秒間のI/Oリクエスト数(転送回数)
rd_sec(rsec)/s... 1秒間の読み込みセクタ数(1セクタ512バイト)
wr_sec(wsec)/s... 1秒間の書き込みセクタ数(1セクタ512バイト)
avgrq-sz......... デバイスへのIOリクエストの平均セクタサイズ
avgqu-sz......... デバイスへのIOリクエストの待ち行列の平均セクタサイズ
await............ デバイスへのIOリクエストの平均待ち時間(単位msec)[待ち行列にいる時間＋処理時間]
svctm............ デバイスへのIOリクエストの平均処理時間(単位msec)
%util............ デバイスへのIOリクエスト中のCPU使用率(ここが継続的に100%だとディスク部分でボトルネックになっている可能性が高い)

/var/log/sa/sa08

00時00分01秒 proc/s cswch/s
00時10分01秒 0.01 15.49
00時20分01秒 0.01 15.53
00時30分01秒 0.01 15.56
00時40分01秒 0.01 15.65
00時50分01秒 0.04 15.87
〜
04時10分01秒 0.01 15.60
04時20分01秒 0.01 15.73
04時30分01秒 0.01 15.53
04時40分01秒 0.40 17.58
04時50分01秒 0.03 15.94
05時00分01秒 0.01 15.67
〜
19時10分01秒 0.01 15.68
19時20分01秒 0.01 15.53
19時30分01秒 0.01 15.44
19時40分01秒 0.04 16.49
19時50分01秒 0.14 36.60
20時00分01秒 0.01 16.36
20時10分01秒 0.03 16.35

00時00分01秒 DEV tps rd_sec/s wr_sec/s avgrq-sz avgqu-sz await svctm %util
〜
01時20分01秒 dev252-0 0.10 0.00 0.87 9.12 0.00 1.18 0.89 0.01
01時30分01秒 dev252-0 0.10 0.00 0.89 9.08 0.00 1.02 0.76 0.01
〜
04時00分01秒 dev252-0 0.11 0.00 1.04 9.75 0.00 0.62 0.59 0.01
04時10分01秒 dev252-0 0.10 0.00 1.06 10.19 0.00 0.73 0.68 0.01
04時20分01秒 dev252-0 0.09 0.00 0.81 9.04 0.00 0.80 0.72 0.01
04時30分01秒 dev252-0 0.09 0.00 0.77 8.75 0.00 0.81 0.72 0.01
04時40分01秒 dev252-0 0.31 0.00 **18.23 59.67 ** 0.00 1.25 0.29 0.01
04時50分01秒 dev252-0 0.13 0.00 1.31 10.18 0.00 0.92 0.75 0.01
05時00分01秒 dev252-0 0.14 0.00 1.50 10.42 0.00 0.80 0.57 0.01
05時10分01秒 dev252-0 0.13 0.00 1.28 10.11 0.00 0.99 0.68 0.01
05時20分01秒
〜
19時00分01秒 dev252-0 0.12 0.00 1.34 11.11 0.00 0.94 0.69 0.01
19時10分01秒 dev252-0 0.11 0.00 1.00 9.09 0.00 1.26 0.88 0.01
19時20分01秒 dev252-0 0.09 0.00 0.84 9.16 0.00 1.15 0.85 0.01
19時30分01秒 dev252-0 0.09 0.00 0.83 9.02 0.00 1.36 0.89 0.01
19時40分01秒 dev252-0 0.14 0.00 1.36 9.83 0.00 0.92 0.59 0.01
19時50分01秒 dev252-0 1.64 3.67 　187.16 116.59 0.02 9.55 0.37 0.06
20時00分01秒 dev252-0 0.11 0.00 1.07 10.00 0.00 0.92 0.75 0.01

---

/var/log/sar/sa09

00時00分01秒    proc/s   cswch/s
00時10分01秒      0.02     16.91
00時20分01秒      0.01     16.44
00時30分01秒      0.02     16.94
00時40分01秒      0.01     16.56
〜
04時20分01秒      0.01     18.51
04時30分01秒      0.01     16.57
04時40分02秒      0.01     16.63
04時50分01秒      0.50     55.70
05時00分01秒      0.01     16.22
05時10分01秒      0.01     16.56

00時00分01秒       DEV       tps  rd_sec/s  wr_sec/s  avgrq-sz  avgqu-sz     await     svctm     %util
00時50分01秒  dev252-0      0.13      0.59      1.01     12.80      0.00      0.85      0.65      0.01
01時00分01秒  dev252-0      0.08      0.00      0.76      9.12      0.00      0.98      0.74      0.01
〜
04時00分01秒  dev252-0      0.09      0.00      0.84      9.16      0.00      0.89      0.64      0.01
04時10分01秒  dev252-0      0.09      0.00      0.75      8.62      0.00      1.29      0.83      0.01
04時20分01秒  dev252-0      0.18      0.00      2.42     13.41      0.00      0.73      0.44      0.01
04時30分01秒  dev252-0      0.09      0.00      0.77      8.75      0.00      0.98      0.72      0.01
04時40分02秒  dev252-0      0.09      0.00      0.81      9.04      0.00      1.07      0.81      0.01
04時50分01秒  dev252-0     12.71   **207.21    25.53    18.31**   0.01      0.70      0.37      0.47
05時00分01秒  dev252-0      0.10      0.00      0.93      9.33      0.00      1.02      0.77      0.01

---

/var/log/cron

Apr  8 04:34:01 ik1-331-25789 run-parts(/etc/cron.daily)[32120]: starting makewhatis.cron
Apr  8 04:34:02 ik1-331-25789 run-parts(/etc/cron.daily)[32280]: finished makewhatis.cron
Apr  8 04:34:02 ik1-331-25789 run-parts(/etc/cron.daily)[32120]: starting mlocate.cron
Apr  8 04:34:02 ik1-331-25789 run-parts(/etc/cron.daily)[32291]: finished mlocate.cron
Apr  8 04:34:02 ik1-331-25789 run-parts(/etc/cron.daily)[32120]: starting prelink
Apr  8 04:34:02 ik1-331-25789 run-parts(/etc/cron.daily)[32303]: finished prelink
Apr  8 04:34:02 ik1-331-25789 run-parts(/etc/cron.daily)[32120]: starting readahead.cron
Apr  8 04:34:02 ik1-331-25789 run-parts(/etc/cron.daily)[32315]: finished readahead.cron
Apr  8 04:34:02 ik1-331-25789 run-parts(/etc/cron.daily)[32120]: starting tmpwatch
Apr  8 04:34:02 ik1-331-25789 run-parts(/etc/cron.daily)[32353]: finished tmpwatch
Apr  8 04:34:02 ik1-331-25789 anacron[31999]: Job `cron.daily' terminated
Apr  8 04:34:02 ik1-331-25789 anacron[31999]: Normal exit (1 job run)
Apr  8 04:40:01 ik1-331-25789 CROND[32355]: (root) CMD (/usr/lib64/sa/sa1 1 1)
Apr  8 04:43:01 ik1-331-25789 CROND[32361]: (root) CMD (run-parts /etc/cron.hourly)
Apr  8 04:43:01 ik1-331-25789 run-parts(/etc/cron.hourly)[32361]: starting 0anacron
Apr  8 04:43:01 ik1-331-25789 run-parts(/etc/cron.hourly)[32370]: finished 0anacron
Apr  8 04:50:01 ik1-331-25789 CROND[32372]: (root) CMD (/usr/lib64/sa/sa1 1 1)
〜
Apr  8 19:40:01 ik1-331-25789 CROND[455]: (root) CMD (/usr/lib64/sa/sa1 1 1)
Apr  8 19:43:01 ik1-331-25789 CROND[528]: (root) CMD (run-parts /etc/cron.hourly)
Apr  8 19:43:01 ik1-331-25789 run-parts(/etc/cron.hourly)[528]: starting 0anacron
Apr  8 19:43:01 ik1-331-25789 run-parts(/etc/cron.hourly)[537]: finished 0anacron
Apr  8 19:50:01 ik1-331-25789 CROND[540]: (root) CMD (/usr/lib64/sa/sa1 1 1)
Apr  8 20:00:01 ik1-331-25789 CROND[546]: (root) CMD (/usr/lib64/sa/sa1 1 1)
Apr  8 20:10:01 ik1-331-25789 CROND[566]: (root) CMD (/usr/lib64/sa/sa1 1 1)
〜
Apr  9 04:43:01 ik1-331-25789 anacron[1834]: Anacron started on 2019-04-09
Apr  9 04:43:01 ik1-331-25789 anacron[1834]: Job `cron.daily' locked by another anacron - skipping
Apr  9 04:43:01 ik1-331-25789 anacron[1834]: Normal exit (0 jobs run)
Apr  9 04:43:01 ik1-331-25789 run-parts(/etc/cron.hourly)[1836]: finished 0anacron
Apr  9 04:48:01 ik1-331-25789 anacron[1666]: Job `cron.daily' started
Apr  9 04:48:01 ik1-331-25789 run-parts(/etc/cron.daily)[1838]: starting logrotate
Apr  9 04:48:01 ik1-331-25789 run-parts(/etc/cron.daily)[1847]: finished logrotate
Apr  9 04:48:01 ik1-331-25789 run-parts(/etc/cron.daily)[1838]: starting makewhatis.cron
Apr  9 04:48:01 ik1-331-25789 run-parts(/etc/cron.daily)[2002]: finished makewhatis.cron
Apr  9 04:48:01 ik1-331-25789 run-parts(/etc/cron.daily)[1838]: starting mlocate.cron
Apr  9 04:48:03 ik1-331-25789 run-parts(/etc/cron.daily)[2013]: finished mlocate.cron
Apr  9 04:48:03 ik1-331-25789 run-parts(/etc/cron.daily)[1838]: starting prelink
Apr  9 04:48:04 ik1-331-25789 run-parts(/etc/cron.daily)[2069]: finished prelink
Apr  9 04:48:04 ik1-331-25789 run-parts(/etc/cron.daily)[1838]: starting readahead.cron
Apr  9 04:48:04 ik1-331-25789 run-parts(/etc/cron.daily)[2081]: finished readahead.cron
Apr  9 04:48:04 ik1-331-25789 run-parts(/etc/cron.daily)[1838]: starting tmpwatch
Apr  9 04:48:04 ik1-331-25789 run-parts(/etc/cron.daily)[2119]: finished tmpwatch

補足情報（FW/ツールのバージョンなど）

使用OSバージョン：CentOS release 6.9 (Final)

Comments

[cateye]

情報が少なすぎるようですが、swapはどうですか？

[kenji267]

vmstatでioが発生しているときのswapを確認してみましたが発生していないようです。

[k-nishiyama]

朝4時台に秒間10kBって、ただのログローテでは・・・？

[kenji267]

そういえばこの時間はログローテなんでしょうね。
この時に発生しているログってあるんでしょうか？

[kenji267]

あとDISK I/Oが発生している時点から、合理的に何が発生しているのか調査する方法を知りたいです。
今ですと推測の状況です。

[kenji267]

朝４時のログローテの件ですが、この時のメモリがどうなっているかがわかるログってありますでしょうか？

[k-nishiyama]

> ログローテのログ
cronのログファイルに記述されていると思いますよ
> ログローテ実行時のメモリ利用状況
sarがインストールされているならば確認できますよ

Answer 1

事象が定期的に発生するのであれば、cron ジョブが原因の可能性が考えられます。
例えば、1日に 1回なのであれば、/etc/cron.daily/ 以下のものです。

# ls -1 /etc/cron.daily/
logrotate
makewhatis.cron
mlocate.cron
prelink
readahead.cron
tmpwatch

logrotate の他に、makewhatis.cron, mlocate.cron も書き込みが多いと思います。

ジョブの開始時刻は /var/log/cron に記録されますので、ディスク I/O の記録と照合するとどのジョブなのかわかるかもしれません。

Comments

[kenji267]

コメントありがとうございます。
朝の４時あたりのディスク I/O の発生要因に、/var/log/cronを確認し、上記が要因の１つだということがわかりました。
他にも要因があるようですが、もしそのジョブの手がかりを見つけていく方法があれば何かあればご教授いただけると有り難いですが、きっかけが掴めたと思うんで調査してみます。
ありがとうございました。

Answer 2

質問記載欄の文字数制限のため一部を下記に記載

sarコマンド
(メモリ使用領域)
kbmemfree... 物理メモリの空き容量
kbmemused... 使用中の物理メモリ量
%memused.... 物理メモリの使用率
kbbuffers... バッファとして使用されている物理メモリの容量
kbcached.... キャッシュとして使用されている物理メモリの容量
kbcommit.... 事前に確保されているメモリ容量
%commit..... 事前に確保されているメモリ容量の割合

(スワップ領域)
kbswpfree... スワップ領域の空き容量
kbswpused... スワップ領域の使用量
%swpused.... スワップ領域の使用率
kbswpcad.... キャッシュされたスワップメモリ容量
%swpcad..... 使用されたスワップスペースに対する、キャッシュされたスワップメモリ使用率

調査例３　追記

/var/log/sa/sar08
00時00分01秒 kbmemfree kbmemused %memused kbbuffers kbcached kbcommit %commit
00時10分01秒 275880 744016 72.95 190364 360116 306312 9.83
00時20分01秒 275904 743992 72.95 190364 360120 306312 9.83
〜
04時00分01秒 275556 744340 72.98 190372 360240 306892 9.85
04時10分01秒 275400 744496 73.00 190372 360240 306892 9.85
04時20分01秒 275508 744388 72.99 190372 360244 306892 9.85
04時30分01秒 275516 744380 72.99 190372 360244 306892 9.85
04時40分01秒 275680 744216 72.97 190372 360252 306312 9.83
04時50分01秒 275820 744076 72.96 190372 360252 306312 9.83
05時00分01秒 275540 744356 72.98 190372 360260 306312 9.83
05時10分01秒 275696 744200 72.97 190376 360272 306312 9.83
05時20分01秒 275540 744356 72.98 190376 360272 306312 9.83
05時30分01秒 276688 743208 72.87 190376 360276 304812 9.78
〜
19時00分01秒 275052 744844 73.03 190376 360736 306312 9.83
19時10分01秒 275184 744712 73.02 190376 360740 306312 9.83
19時20分01秒 275052 744844 73.03 190376 360744 306312 9.83
19時30分01秒 275284 744612 73.01 190376 360744 306312 9.83
19時40分01秒 273508 746388 73.18 190376 360752 311052 9.98
19時50分01秒 269756 750140 73.55 190432 363280 311052 9.98
20時00分01秒 269840 750056 73.54 190432 363284 311052 9.98
20時10分01秒 267924 751972 73.73 190432 363292 315792 10.13
20時20分01秒 265860 754036 73.93 190432 363296 320532 10.28
20時30分01秒 265760 754136 73.94 190432 363300 320532 10.28
20時40分01秒 265752 754144 73.94 190432 363300 320532 10.28
20時50分01秒 266000 753896 73.92 190432 363304 320532 10.28
〜
平均値: 274120 745776 73.12 190384 360921 309321 9.92

00時00分01秒 kbswpfree kbswpused %swpused kbswpcad %swpcad
00時10分01秒 2097148 0 0.00 0 0.00
00時20分01秒 2097148 0 0.00 0 0.00
〜
04時00分01秒 2097148 0 0.00 0 0.00
04時10分01秒 2097148 0 0.00 0 0.00
04時20分01秒 2097148 0 0.00 0 0.00
04時30分01秒 2097148 0 0.00 0 0.00
04時40分01秒 2097148 0 0.00 0 0.00
04時50分01秒 2097148 0 0.00 0 0.00
05時00分01秒 2097148 0 0.00 0 0.00
〜
19時00分01秒 2097148 0 0.00 0 0.00
19時10分01秒 2097148 0 0.00 0 0.00
19時20分01秒 2097148 0 0.00 0 0.00
19時30分01秒 2097148 0 0.00 0 0.00
19時40分01秒 2097148 0 0.00 0 0.00
19時50分01秒 2097148 0 0.00 0 0.00
20時00分01秒 2097148 0 0.00 0 0.00
20時10分01秒 2097148 0 0.00 0 0.00
20時20分01秒 2097148 0 0.00 0 0.00
〜
平均値: 2097148 0 0.00 0 0.00

/var/log/sa/sar09
00時00分01秒 kbmemfree kbmemused %memused kbbuffers kbcached kbcommit %commit
00時10分01秒 831456 188440 18.48 16320 66604 294388 9.44
00時20分01秒 831356 188540 18.49 16408 66608 294388 9.44
00時30分01秒 831024 188872 18.52 16536 66640 294388 9.44
00時40分01秒 830984 188912 18.52 16624 66644 294388 9.44
〜
4時00分01秒 829612 190284 18.66 18760 66864 290228 9.31
04時10分01秒 829380 190516 18.68 18864 66864 290228 9.31
04時20分01秒 829040 190856 18.71 19080 66996 290228 9.31
04時30分01秒 828908 190988 18.73 19184 66996 290228 9.31
04時40分02秒 828884 191012 18.73 19288 67000 290228 9.31
04時50分01秒 718332 301564 29.57 61148 87352 289648 9.29
05時00分01秒 718060 301836 29.59 61252 87360 289648 9.29
05時10分01秒 717952 301944 29.61 61364 87364 289648 9.29
〜
平均値: 731271 288625 28.30 58003 84483 298606 9.58

00時00分01秒 kbswpfree kbswpused %swpused kbswpcad %swpcad
00時10分01秒 2097148 0 0.00 0 0.00
00時20分01秒 2097148 0 0.00 0 0.00
00時30分01秒 2097148 0 0.00 0 0.00
〜
04時00分01秒 2097148 0 0.00 0 0.00
04時10分01秒 2097148 0 0.00 0 0.00
04時20分01秒 2097148 0 0.00 0 0.00
04時30分01秒 2097148 0 0.00 0 0.00
04時40分02秒 2097148 0 0.00 0 0.00
04時50分01秒 2097148 0 0.00 0 0.00
05時00分01秒 2097148 0 0.00 0 0.00
05時10分01秒 2097148 0 0.00 0 0.00
〜
平均値: 2097148 0 0.00 0 0.00

Answer 3

どらくらいのDISK I/Oかと直接は断定できないが備忘記録として記載。

調査例3でDISK I/Oが少し他と比べて高いが２箇所ある。

1. 4/8の夜にwrite箇所
2. 4/9の午前4時ころにread箇所

下記のように想定している。
1に関してはdsatをダウンロードしたため。
/var/log/messages
Apr 8 19:42:44 ik1-331-25789 yum info Installed: dstat-0.7.0-3.el6_9.1.noarch

2に関してはこの時4時ころの状況を見るためこの時間あたりにvmstat -t 20を実行していたため。(たまたま目が覚めたので）

（そもそもそれ以外にあまりVPSサーバを利用していないというのが残念・・・）