質問: ### 前提・実現したいこと さくらVPSを使用しております。 DISK I/Oが発生している要因を調査したいと考えています。 時々一時的に急激に上がったりしています。 なお特にアプリは動かしてはいません。 dstat -taf で、IO負荷を確認しています。 dsk/vdaで時々、writに値が発生しています。 これは書き込みが発生しているという認識でよろしいでしょうか。 その書き込みはどうやって発生しているか確認する方法はありますでしょうか。 ご教授のほどどうかよろしくお願いします。 ### 調査したい箇所 一時的に増加している。 ![DISK I/O](https://teratail-v2.storage.googleapis.com/uploads/contributed_images/2f06a49ce9e36167ad969a38d2a06a6e.png) ### 調査例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 ![イメージ説明](https://teratail-v2.storage.googleapis.com/uploads/contributed_images/9010f3c2e0f6e5831e3ebcf7f04d9131.png) 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)
回答: 事象が定期的に発生するのであれば、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 の記録と照合するとどのジョブなのかわかるかもしれません。