ʍoɹɐɥsのブ口グ

ส็็็็็็็็็็็็็็็็็็็็็็็็็ ส็็็็็็็็็็็็็็็็็็็็็็็็็ ส็็็็็็็็็็็็็็็็็็็็็็็็็ ส็็็็็็็็็็็็็็็็็็็็็็็็็ ส็็็็็็็็็็็็็็็็็็็็็็็็็ ส็็็็็็็็็็็็็็็็็็็็็็็็็ ส็็็็็็็็็็็็็็็็็็็็็็็็็ ส็็็็็็็็็็็็็็็็็็็็็็็็็ ส็็็็็็็็็็็็็็็็็็็็็็็็็ ส็็็็็็็็็็็

さくらのVPSのIOが遅い時間帯

とある石狩のVPS(1Gプラン, HDD)の定期iopingによるデータです。 標本は3868サンプル(2週間くらい)で、5分毎にdateとioping -R /を走らせた出力データです。この計測中は他に動いてるデーモン(DBとか)はありません。せいぜいlogrotateやjournaldくらいです。

iopingの-Rは4k単位のリクエストなので、わりかし細かいIOです。シーケンシャルだとまた違った結果が出るかもしれません。

時間 スループット[MiB/s] 標準偏差[MiB/s]
00-01時 18.67 3.28
01-02時 18.76 3.22
02-03時 18.69 2.50
03-04時 13.04 7.37
04-05時 16.76 5.58
05-06時 18.00 4.45
06-07時 15.76 6.76
07-08時 17.44 4.62
08-09時 18.21 3.76
09-10時 19.25 2.28
10-11時 18.78 3.01
11-12時 18.19 4.08
12-13時 19.11 2.77
13-14時 19.26 2.75
14-15時 18.62 3.07
15-16時 18.73 2.78
16-17時 18.80 2.54
17-18時 18.95 2.92
18-19時 18.40 2.59
19-20時 18.66 3.22
20-21時 18.37 3.55
21-22時 18.27 3.50
22-23時 18.86 2.73
23-00時 19.05 2.53

さくらのVPSは稀にディスクIOがとても遅くなることが知られています。勝手に推測すると、ホスト自身の定期バックアップや同じホストの別インスタンスのバックアップタスクが動いてる、などなどいろいろあるのですが、とにかく深夜~朝にかけて遅い場合があるのは経験上でもそうだと思います。 データを俯瞰すると4k単位IOのスループットはだいたい平均で18MiB/sであることが分かります(スループットは平均値です)。一番遅いのは深夜3時~4時で、偏差も最も大きくなっています。次に遅いのは朝6時~7時。比べて昼のスループット/偏差はとても安定しています。

上のデータから、このインスタンスでは3時~8時まではIO性能が少し落ちてることが分かります。このインスタンスでディスクIOの頻発するタスクを走らせるなら、深夜1時~2時頃がよいでしょう。…もっと言えば、深夜よりも普通に白昼堂々、昼間に走らせた方がホストへのIO負荷が少ないようにも思えます。

ちなみにこちらは ioping -R -s 256k (256kb単位のIO)の場合です。

時間 スループット[MiB/s] 標準偏差[MiB/s]
00-01時 393.68 55.77
01-02時 386.37 50.73
02-03時 387.81 49.18
03-04時 281.90 145.60
04-05時 354.32 103.84
05-06時 379.16 73.45
06-07時 334.80 130.62
07-08時 364.30 80.72
08-09時 380.09 69.34
09-10時 396.88 48.79
10-11時 397.98 49.65
11-12時 393.03 60.45
12-13時 398.03 52.64
13-14時 395.82 53.41
14-15時 392.11 54.83
15-16時 392.46 58.09
16-17時 393.46 54.36
17-18時 391.10 59.62
18-19時 389.75 42.89
19-20時 391.76 55.55
20-21時 393.91 58.90
21-22時 389.91 61.68
22-23時 394.47 58.25
23-00時 387.01 68.03

やはり3時以降の偏差が大きくなっています。

※ 遅い時間帯はリージョンやホストによっても違うかもしれません

ところで、データをかき集めるのにpythonの3.4を使ったらstatisticsというモジュールが追加されていてとても楽でした。時間のパースだけは外部パッケージのdateutilを使っています。

#!/usr/bin/env python
# -*- Mode: python; tab-width: 4; indent-tabs-mode: nil; coding: utf-8; -*-

import sys
import re
import dateutil.parser
import collections
import statistics


req_re = re.compile('([\d.k ]+) requests completed in ' +
                    '([\d.s ]+), ([\d.k ]+) iops, ([\d. MKiB/s]+)')


def parse(filename):
    data = {}
    cur_date = None
    p = dateutil.parser.parser()
    nsample = 0
    with open(filename, 'r') as fp:
        for line in fp.readlines():
            if line.startswith('#'):
                cur_date = p.parse(line.replace('#', ''))
            f = req_re.search(line)
            if f:
                assert(cur_date is not None)
                data[cur_date] = f.groups()
                cur_date = None
                nsample += 1
    # print(nsample, 'samples')
    return data


def main():
    if len(sys.argv) < 2:
        print('need log file')
        return
    data = parse(sys.argv[1])
    total = collections.defaultdict(list)
    for k, v in data.items():
        hour = k.hour
        tp = v[3].strip()
        if tp.endswith('MiB/s'):
            tp = float(tp.replace('MiB/s', ''))
        elif tp.endswith('KiB/s'):
            tp = float(tp.replace('KiB/s', '')) / 1024
        else:
            raise Exception('!!??')
        total[hour].append(tp)
    print('時間|スループット[MiB/s]|標準偏差[MiB/s]')
    print('----|----|----')
    for k, v in total.items():
        mean = statistics.mean(v)
        stdev = statistics.stdev(v)
        print('{:02d}-{:02d}時|{:.2f}|{:.2f}'.format(k, (k+1)%24, mean, stdev))


if __name__ == '__main__':
    main()

いま見ると、関数parse()はiteratorにしたほう自然でしたね。

データはdateとioping -Rをsystemd-timerで5分毎に走らせただけの酷い代物。

## Sun Feb 15 08:00:01 JST 2015

--- / (ext4 /dev/vda2) ioping statistics ---
8.17 k requests completed in 3.00 s, 2.77 k iops, 10.8 MiB/s
min/avg/max/mdev = 99 us / 360 us / 143.7 ms / 3.14 ms


## Sun Feb 15 08:05:14 JST 2015

--- / (ext4 /dev/vda2) ioping statistics ---
671 requests completed in 3.00 s, 224 iops, 896.6 KiB/s
min/avg/max/mdev = 142 us / 4.46 ms / 438.2 ms / 17.9 ms

...

ちょっと前まで2.7系ばっかり使っていたのですが、そろそろ3系に移行してもいいかなと思う今日この頃。