VPSはオンラインなのに、Linuxのディスク読み取りが18秒待ちになった

デバッグの話に入る前に、一つだけ明確にしておきたいことがあります。私はFDCServersに対して全体として悪い印象を持っていません。この記事はFDCServersを避けるよう勧めるレビューではなく、同社のインフラ全体を評価するものでもありません。ある期間、私が使っていた一台のVPSで、かなり難しい問題が起きたという話です。

それまではVPSは普通に動き、本番トラフィックも問題なく処理していました。ところが、ある時から状況が変わりました。通常のリクエストに異常な時間がかかるようになり、ページはゆっくり開いた後、まったく開かなくなることもありました。逆に、原因を詳しく調べる前に何事もなかったような状態へ戻ることもありました。

最悪のタイミングでは、次の値を記録しました。

CPU iowait:       97–100%
I/O PSI full:     ~95–98%
read latency:     up to 18.7 seconds
flush latency:    up to 53.6 seconds
I/O queue depth:  128+

Nginxは動いていました。backendも動いていました。VMもオンラインでした。それでも、実際の処理はほとんど前に進んでいませんでした。

本番障害そのものはもちろん困りましたが、デバッグは純粋に面白かったです。Linuxが好きな理由の一つが、まさにこういう場面にあります。外から見ると正常そうなマシンでも、複数の独立したkernel interfaceを追うことで、どこで実処理が止まっているのかを絞り込めます。この記事の主題はその過程であって、FDCServersが良いか悪いかを判定することではありません。

active (running) は、ほとんど何も保証していなかった

最初は定番の確認から始めました。

top
free -h
df -h
systemctl status nginx

正常な時間帯は、おおむね次の状態でした。

D-state processes: 0
CPU iowait:        ~0%
disk latency:      ~2–4 ms
I/O PSI some:      0.04
I/O PSI full:      0.04

この瞬間だけSSHで入っていたら、「VPSは正常」と判断していたと思います。しかし通常トラフィックが戻ると、状態は一変しました。断続的な障害では、正常時のsnapshotだけを見ても障害時の実態は分かりません。問題が起きている最中に証拠を取る必要がありました。

調査の方向を変えた iostat

r_await = 18744 ms
f_await = 53561 ms
aqu-sz  = 128.54
util    ≈ 100%
read    = 88 KB/s

完了したreadは約18.7秒、flushは約53.6秒。平均queueは128を超えているのに、実際のread throughputはわずか88 KB/sでした。

これは、大量の有効な処理をこなしているためにstorageが忙しい状態には見えませんでした。virtual block pathはほぼ飽和しているのに、ほとんど仕事を完了できていません。utilizationが高いだけなら障害とは言えません。しかし、巨大なlatency、大きなqueue、停止したtask、極端に低いthroughput、失敗するrequestが同時に出ているなら話は別です。

iowait 単独で診断しないことにした

blocked processes: 4–9
CPU iowait:        97–100%
CPU idle:          0%

「CPUが100%ディスク待ちだった」と言いたくなります。直感的な説明としては分かりやすいのですが、Linuxのaccountingはそれほど単純ではありません。iowaitはディスクそのものを直接計測した値ではないため、私はこれを一つの症状として扱い、別の指標でも確認することにしました。

PSIはI/Oが実処理を止めていることを示した

cat /proc/pressure/io

ある深刻な時間帯では次の値でした。

some avg10=99.14
full avg10=95.55

その後の再現では、fullは98%近くまで上がりました。I/O pressureにおけるsomeは少なくとも一部のnon-idle workがI/O待ちになっている時間、fullはすべてのnon-idle taskが同時にI/O待ちになっている時間を表します。100%近い値は、単に「ディスクが忙しい」という話ではありません。workloadが前に進める時間そのものがほとんど残っていない状態です。

D-state を見ると、一つのprocessだけを疑えなくなった

ps -eo state,pid,ppid,etime,wchan:50,comm,args | awk 'NR==1 || $1 ~ /^D/'

一つのprocessが短時間D-stateに入っただけではstorage障害とは言えません。重要だったのは、どのprocessが同時に止まっていたかです。jbd2、systemd-journald、Nginx worker、Nginx cache process、その他のfilesystem activityが一緒にblockしていました。

backendだけが止まるならbackendを調べます。NginxだけならNginxを調べます。しかしNginx、system journal、EXT4 journal threadが同時に進まないなら、個別のprocessより共通依存先を見るべきです。このケースではfilesystemとその下のstorage pathでした。

Kernel stackから、さらに下のlayerが見えた

EXT4 journal threadは次のpathにいました。

wait_on_buffer
jbd2_log_wait_commit
jbd2_journal_commit_transaction

Nginx workerは通常のfilesystem read pathにいました。

folio_wait_bit_common
filemap_read
generic_file_read_iter
ext4_file_read_iter
vfs_read
pread64

kernelは一度、次のようにも報告しました。

INFO: task nginx blocked for more than 122 seconds.

その間もsystemctl status nginxはactive (running)と表示できます。どちらも正しいのです。processは存在していても、Nginx taskが2分以上有効な処理を完了できないことはあります。processがrunningであることと、serviceがhealthyであることは別です。

最も分かりやすい比較は約3ミリ秒だった

Nginx経由のrequestは失敗しました。

HTTP=000
SSL connection timeout

そこでNginxを迂回し、local backendへ直接アクセスしました。

connect = 0.000423 s
TTFB    = 0.003063 s
total   = 0.003139 s

約3 msです。このテストではHTTP statusそのものは重要ではありません。backendはconnectionを受け付け、requestを処理し、ほぼ即座にresponseを返しました。同じタイミングで、Nginx workerはEXT4 read pathの中にいました。

application execution       → progressing normally
filesystem-backed web path  → not progressing normally

調べるほど、application自身が原因という説明は成立しにくくなりました。

同じVPSが約30秒で崩れることもあった

ある再現テストの前は:

HTTP:          200
D-state:       0
CPU iowait:    3%
r_await:       ~1.18 ms
I/O PSI full:  ~2.95%

約30秒後:

D-state:       4
CPU iowait:    91%
CPU idle:      0%
I/O PSI some:  86.11%
I/O PSI full:  78.02%
r_await:       236.50 ms
HTTP:          000

さらに悪化すると:

CPU iowait:    96–100%
I/O PSI full:  ~98%
HTTPS queue:   512
HTTP:          000

workloadを外すと、逆方向の変化もすぐに起きました。

D-state:      0
CPU iowait:   6%
r_await:      ~0.98 ms
queue depth:  ~0.07
HTTP:         200

断続的なインフラ障害が難しい理由はここです。10分後に同じVMを調べた人が「disk latencyは1ms未満だった」と報告しても、その人が間違っているとは限りません。単に別のstateを見ているだけです。

Latencyが0でも、安心できないことがある

明らかに異常な状態なのに、iostatでr_await = 0になったintervalもありました。同時に高いiowait、D-state process、未完了I/O、ほぼゼロのcompleted read、ほぼゼロのthroughputが出ていました。

完了したoperationを基にした平均値は、sampling interval内でほとんど何も完了しない場合、情報量が下がります。0だからといってreadが瞬時に完了したとは限りません。stuckしたoperationを表せるだけのcompletionが存在しないこともあります。

この件以降、latencyだけを見ることはやめました。IOPS、throughput、queue depth、in-flight I/O、D-state、PSI、実際のrequest completionをセットで見ます。

一つのincidentが長いsupport調査になった

最初の深刻な障害は元のインフラでのscheduled backupと重なっており、FDCServersもbackupが動いていたことを確認しました。最初の説明候補としては妥当でした。しかしbackup終了後、元のbackup window外でも同じ種類のstorage stallを再現しました。

問題は複数日にわたって再発しました。あるincidentではservice log上、VPSがその後4時間41分15秒利用できませんでした。ただしstorage stallそのものがVMをそのstateにしたとは証明できません。それには私が持っていないhost-side情報が必要です。

application
    ↓
Linux VFS
    ↓
EXT4
    ↓
virtual block device
    ↓
?

この「?」の先にはvirtualization、host queue、storage network、distributed storage、physical media、schedulerなど、guestから見えないlayerがあります。私が確認できたのはfailureが表面化している境界であって、physical root causeではありません。

FDCServersは問題を内部でescalateし、最終的にVPSを別nodeへmigrationしました。その後もguest側から深刻なstorage stallを記録しました。これはFDCServersのすべてのnodeにstorage問題があったことを証明しません。私の視点では、自分のVPSに起きていた問題が解消されていなかった、というだけです。

それでもFDCServersを否定する記事だとは考えていない

一つのinfrastructure incidentからprovider全体への評価を作るのは簡単です。私はそうしたくありません。

通常のoperating modelそのものが自分のworkloadに合わないserviceと、断続的で再現しづらく、切り分けに時間がかかるinfrastructure problemは別です。私のFDCServersでの経験は後者に近いものでした。

incident以前、VPSは正常に動いており、本番trafficも処理していました。supportは調査し、解決を試みました。最終的に私は十分なevidenceを集め、そのVPSへ本番を依存させ続けないと判断しました。

私はserviceのcancelとrefundを依頼し、FDCServersは返金してくれました。これは全体的な印象を考えるうえで重要です。

現在のインフラを再テストしていないため、今のFDCServers VPSがどう動くのかは分かりません。また、私のinstanceで起きたことがfleet全体を代表していたという証拠もありません。インフラは常に変化します。一台のVPSでの難しいincidentを、provider全体への永続的な評価にはしません。そして、ここでFDCServersを推薦しているわけでもありません。自分に何が起きたかを書いているだけです。

一番面白かったのはLinuxそのものだった

Downtimeはつらかったですが、investigationは楽しかったです。問題の境界を見つける過程そのものが面白かった。

physical root causeを特定できるほどのvisibilityはありませんでした。私が知りたかったのは、もっと単純なことです。どのlayerでuseful workが完了しなくなるのか。

backendは約3msで応答していました。Nginxはactiveと表示される一方、kernel stackではEXT4 read内で待っていました。vmstatはblocked processと極端なI/O waitを示し、PSIはI/O stallがworkloadのほぼすべてを占めていることを示しました。iostatには巨大なlatencyとqueueingが出て、D-stateでは無関係なprocessが同時に待っていました。kernelはNginx taskが122秒以上blockedしているとも報告しました。

一つのmetricが問題を解いたわけではありません。複数のsignalが同じ方向を指したことが決め手でした。これがLinuxを好きな理由の一つです。「サイトが時々開かない」という曖昧な現象から、useful workが止まっているlayerまで段階的に絞り込めます。

今使っているデバッグ手順

top
free -h
df -h

date -u
uptime
cat /proc/pressure/io
cat /proc/pressure/memory
cat /proc/pressure/cpu
vmstat 1 10
iostat -x 1 10
ps -eo state,pid,ppid,etime,wchan:50,comm,args | awk 'NR==1 || $1 ~ /^D/'
ss -lntp
journalctl -k --since "30 min ago" --no-pager

可能ならrequest pathもlayerごとに分けて試します。

public request
      ↓
reverse proxy
      ↓
direct backend
      ↓
filesystem
      ↓
block device

今は「なぜserverが遅いのか」だけを聞きません。どのlayerでuseful workが完了しなくなるのか。この問いの方が、はるかに良い実験につながります。

最後のルール: rebootする前に証拠を取る

rebootはproductionを復旧するために正しい判断かもしれません。しかし同時に、最も価値のあるdiagnostic stateを消してしまう可能性があります。

Before reboot:
D-state:     high
I/O PSI:     ~97%
iowait:      ~100%
queues:      large
requests:    failing

After reboot:
D-state:     0
latency:     milliseconds
requests:    healthy

可用性とbusiness impactが許すなら、まずUTC timestamp、PSI、vmstat、iostat、D-state、wchan、kernel message、socket queue、request timingを保存してから復旧します。

Serverは動いていた。Workloadは動いていなかった。

最終的にどのhost-side componentがincidentを引き起こしたのかは分かりません。特定のSSDが故障したとも、特定のstorage nodeが原因だったとも、virtual block deviceの裏側で何が起きていたとも証明できません。

それでもLinux guest内部から確認できた事実だけで十分でした。

read latency:       up to 18.7 s
flush latency:      up to 53.6 s
I/O PSI full:       almost 100%
iowait:             almost 100%
I/O queue:          128+
Nginx:              blocked in filesystem reads
EXT4/jbd2:          blocked waiting for I/O
direct backend:     ~3 ms
HTTP through Nginx: timing out

applicationと問題のlayerを切り分け、運用判断をするには十分でした。FDCServersはVPS料金を返金し、私は別の環境へ移りました。一つの難しいinfrastructure incidentをprovider全体への判定にはしません。

残った教訓の方が重要です。processはrunning、serviceはactive、VMはonline、pingも通る。それでもmachineはほとんどuseful workを完了していないことがあります。

Linuxには、その違いを見分けるだけの証拠があります。failureが残っているうちに、正しい問いを投げればいいのです。