質問をすることでしか得られない、回答やアドバイスがある。

15分調べてもわからないことは、質問しよう!

ただいまの
回答率

88.79%

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

解決済

回答 3

投稿 編集

  • 評価
  • クリップ 3
  • VIEW 1,291

kenji267

score 50

前提・実現したいこと

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

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

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

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

調査したい箇所

一時的に増加している。
DISK I/O

調査例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

000001秒    proc/s   cswch/s
0010010.02     16.91
0020010.01     16.44
0030010.02     16.94
0040010.01     16.560420010.01     18.51
0430010.01     16.57
0440020.01     16.63
0450010.50     55.70
0500010.01     16.22
0510010.01     16.56

000001秒       DEV       tps  rd_sec/s  wr_sec/s  avgrq-sz  avgqu-sz     await     svctm     %util
005001秒  dev252-0      0.13      0.59      1.01     12.80      0.00      0.85      0.65      0.01
010001秒  dev252-0      0.08      0.00      0.76      9.12      0.00      0.98      0.74      0.01040001秒  dev252-0      0.09      0.00      0.84      9.16      0.00      0.89      0.64      0.01
041001秒  dev252-0      0.09      0.00      0.75      8.62      0.00      1.29      0.83      0.01
042001秒  dev252-0      0.18      0.00      2.42     13.41      0.00      0.73      0.44      0.01
043001秒  dev252-0      0.09      0.00      0.77      8.75      0.00      0.98      0.72      0.01
044002秒  dev252-0      0.09      0.00      0.81      9.04      0.00      1.07      0.81      0.01
045001秒  dev252-0     12.71   **207.21    25.53    18.31**   0.01      0.70      0.37      0.47
050001秒  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)

  • 気になる質問をクリップする

    クリップした質問は、後からいつでもマイページで確認できます。

    またクリップした質問に回答があった際、通知やメールを受け取ることができます。

    クリップを取り消します

  • 良い質問の評価を上げる

    以下のような質問は評価を上げましょう

    • 質問内容が明確
    • 自分も答えを知りたい
    • 質問者以外のユーザにも役立つ

    評価が高い質問は、TOPページの「注目」タブのフィードに表示されやすくなります。

    質問の評価を上げたことを取り消します

  • 評価を下げられる数の上限に達しました

    評価を下げることができません

    • 1日5回まで評価を下げられます
    • 1日に1ユーザに対して2回まで評価を下げられます

    質問の評価を下げる

    teratailでは下記のような質問を「具体的に困っていることがない質問」、「サイトポリシーに違反する質問」と定義し、推奨していません。

    • プログラミングに関係のない質問
    • やってほしいことだけを記載した丸投げの質問
    • 問題・課題が含まれていない質問
    • 意図的に内容が抹消された質問
    • 過去に投稿した質問と同じ内容の質問
    • 広告と受け取られるような投稿

    評価が下がると、TOPページの「アクティブ」「注目」タブのフィードに表示されにくくなります。

    質問の評価を下げたことを取り消します

    この機能は開放されていません

    評価を下げる条件を満たしてません

    評価を下げる理由を選択してください

    詳細な説明はこちら

    上記に当てはまらず、質問内容が明確になっていない質問には「情報の追加・修正依頼」機能からコメントをしてください。

    質問の評価を下げる機能の利用条件

    この機能を利用するためには、以下の事項を行う必要があります。

質問への追記・修正、ベストアンサー選択の依頼

  • kenji267

    2019/04/09 21:25

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

    キャンセル

  • kenji267

    2019/04/09 21:37

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

    キャンセル

  • k-nishiyama

    2019/04/10 13:47

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

    キャンセル

回答 3

checkベストアンサー

+4

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

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

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

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

投稿

  • 回答の評価を上げる

    以下のような回答は評価を上げましょう

    • 正しい回答
    • わかりやすい回答
    • ためになる回答

    評価が高い回答ほどページの上位に表示されます。

  • 回答の評価を下げる

    下記のような回答は推奨されていません。

    • 間違っている回答
    • 質問の回答になっていない投稿
    • スパムや攻撃的な表現を用いた投稿

    評価を下げる際はその理由を明確に伝え、適切な回答に修正してもらいましょう。

  • 2019/04/11 20:43

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

    キャンセル

+2

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

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

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

調査例3 追記

/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

投稿

編集

  • 回答の評価を上げる

    以下のような回答は評価を上げましょう

    • 正しい回答
    • わかりやすい回答
    • ためになる回答

    評価が高い回答ほどページの上位に表示されます。

  • 回答の評価を下げる

    下記のような回答は推奨されていません。

    • 間違っている回答
    • 質問の回答になっていない投稿
    • スパムや攻撃的な表現を用いた投稿

    評価を下げる際はその理由を明確に伝え、適切な回答に修正してもらいましょう。

0

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

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

  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サーバを利用していないというのが残念・・・)

投稿

  • 回答の評価を上げる

    以下のような回答は評価を上げましょう

    • 正しい回答
    • わかりやすい回答
    • ためになる回答

    評価が高い回答ほどページの上位に表示されます。

  • 回答の評価を下げる

    下記のような回答は推奨されていません。

    • 間違っている回答
    • 質問の回答になっていない投稿
    • スパムや攻撃的な表現を用いた投稿

    評価を下げる際はその理由を明確に伝え、適切な回答に修正してもらいましょう。

15分調べてもわからないことは、teratailで質問しよう!

  • ただいまの回答率 88.79%
  • 質問をまとめることで、思考を整理して素早く解決
  • テンプレート機能で、簡単に質問をまとめられる

関連した質問

同じタグがついた質問を見る