2週間くらい前の話になりますが、ウチのサービスで起きたオンコール対応についてネタにします。
ディスク使用率が増加してアラートが飛んできた
見ての通り/の使用率が90%に到達。
$ df -h Filesystem Size Used Avail Use% Mounted on /dev/sda3 273G 232G 27G 90% / ...
どのディレクトリが使用率の大半を占めてるのか調べるために、/直下の各ディレクトリごとの使用量を du -shで確認。
しかし、表示された各容量を合計しても明らかに Used 232Gに達していなかった。
ちなみに一番大きかったのは /var/log。
$ sudo du -sh /var/log 96G /var/log
なんでこんなことが起きているのかというと、この記事が参考になった。
du で見つからない巨大ファイルは lsof で見つけるの術 - HsbtDiary(2013-07-24)
lsof コマンドを使うことで、ファイルシステム上は削除されているが、プロセスが掴みっぱなしになっているケースがあるらしい。
というわけで調べてみたら見事にヒット。
/var/log/app/application.log.1 というログファイルをunicornプロセスが掴みっぱなしだった。
ちなみにlsofで確認できた /var/log/app/application.log.1 というファイルは lsコマンドでは表示されない。
$ sudo lsof | grep deleted | sort -k 7 -nr | head ruby 13460 <user> 7w REG 8,3 127222634114 8519684 /var/log/app/application.log.1 (deleted) ruby 11623 <user> 7w REG 8,3 127222632772 8519684 /var/log/app/application.log.1 (deleted) ruby 11620 <user> 7w REG 8,3 127222632251 8519684 /var/log/app/application.log.1 (deleted) ruby 11617 <user> 7w REG 8,3 127222631864 8519684 /var/log/app/application.log.1 (deleted) ruby 11615 <user> 7w REG 8,3 127222631122 8519684 /var/log/app/application.log.1 (deleted) ruby 11612 <user> 7w REG 8,3 127222630172 8519684 /var/log/app/application.log.1 (deleted) ruby 11608 <user> 7w REG 8,3 127222629663 8519684 /var/log/app/application.log.1 (deleted) ruby 11602 <user> 7w REG 8,3 127222629403 8519684 /var/log/app/application.log.1 (deleted) ruby 11600 <user> 7w REG 8,3 127222629403 8519684 /var/log/app/application.log.1 (deleted) ruby 11596 <user> 7w REG 8,3 127222629301 8519684 /var/log/app/application.log.1 (deleted)
何が起きてるの？
Linux上で見えるファイル(ディレクトリエントリ)はinodeを参照しており、プロセスがファイルを掴むときも同様にinodeを参照している。
何らかの原因でディレクトリエントリは消えたけど、プロセスがファイルを掴みっぱなしな状態になって deleted なログファイルを掴んだプロセスが残り続けていた。そんでそのプロセスが参照先のブロックへログの書き込みを継続していたと。これがls上はファイルが見えないのにディスク使用量がどんどん増えていった現象の正体。
ちなみにログローテーションをきっかけにこの現象が発生したと思われる。
サンプルコードでこの現象を再現する
このコードを実行すると、deletedな/tmp/test.logのファイルサイズ増えていく様子がわかる。
#!/usr/bin/ruby io = File.open("/tmp/test.log", "w") warn "# unlink /tmp/test.log" File.unlink("/tmp/test.log") loop do warn "# file usage" puts `lsof -c ruby | grep deleted` warn "# write 1MB data" io.write( "@" * 1024 * 1024 ) io.sync sleep 1 end
# unlink /tmp/test.log # file usage ruby 3987 <user> 7w REG 8,1 0 67149903 /tmp/test.log (deleted) # write 1MB data # file usage ruby 3987 <user> 7w REG 8,1 1048576 67149903 /tmp/test.log (deleted) # write 1MB data # file usage ruby 3987 <user> 7w REG 8,1 2097152 67149903 /tmp/test.log (deleted) # write 1MB data # file usage ruby 3987 <user> 7w REG 8,1 3145728 67149903 /tmp/test.log (deleted) # write 1MB data # file usage ruby 3987 <user> 7w REG 8,1 4194304 67149903 /tmp/test.log (deleted) ...
対処：unicornにシグナル USR1を送る
https://yhbt.net/unicorn/SIGNALS.html が参考になった。
Master Process
...
USR1 - reopen all logs owned by the master and all workers See Unicorn::Util.reopen_logs for what is considered a log.
...
Worker Processes
...
Note: as of unicorn 4.8, the master uses a pipe to signal workers instead of kill(2) for most cases. Using signals still (and works and remains supported for external tools/libraries), however.
USR1 - Reopen all logs owned by the worker process. See Unicorn::Util.reopen_logs for what is considered a log. Log files are not reopened until it is done processing the current request, so multiple log lines for one request (as done by Rails) will not be split across multiple logs.
要するに、unicornプロセスはシグナル USR1 を受け取ると、masterプロセス/workerプロセスが掴んでいるログファイルを開き直してくれる。 具体的にはこんな感じでシグナルを送ればOK。
$ sudo kill -USR1 $(cat /path/to/pids/unicorn.pid)
使用量が一気に減った
これで解消 🎉
$ df -h Filesystem Size Used Avail Use% Mounted on /dev/sda3 273G 114G 146G 44% / ...
deletedなプロセスも綺麗に無くなった。
$ sudo lsof | grep deleted $
