この記事の概要
- 個人のWebサービスで使用している mysqld が、起動・停止を繰り返すようになったよ
- 原因の特定に苦労したよ
- 振り返れば単純なことだけど、知らない自分には気付きにくいことだったので記事にするよ
事象の概要
- Webサービスが 500 エラーを返すようになっていた
- DB（MySQL）に原因があることはすぐに特定できた
- 原因を示すログがすぐに見つからなかったので、特定に苦労した
- mysqld ではなく kernel のログを確認したら解決した
環境
- CentOS 7
- mysql Ver 14.14
詳しい経緯
ある日、個人開発で運営しているWebサービスが、500エラーで動かなくなっていることに気付きました。
同じサーバで動かしている他のサービスは影響がなかったので、DB（MySQL）関係だとは容易に想像が付きました。
実際、systemctlで確認したところstatus:start-preとなっていたので、mysqld が正常に起動していないことが分かりました。
「ほんなら、mysqld をリスタートすれば解決だなー」と思ったのですが、そう上手くはいきませんでした…。
終了・起動をして、再度ステータスを確認するも、またもやstatus:start-preの表示。
起動しない原因がなにかありそうです。
「ならば、MySQL のエラーログを確認しよう」ということで、my.cnf に書いてあるエラーログを見ることに。
しかし、今回のログは特に吐き出されていなさそうです。
他にログの確認方法が無いかを調べます。
すると、journalctlというコマンドがあることを知りました。
というわけで、mysqld のログを確認するためにjournalctl -u mysqldを実行。
2月 03 18:12:59 public-server systemd[1]: Starting MySQL Server...
2月 03 18:13:58 public-server systemd[1]: mysqld.service: control process exited, code=exited status=1
2月 03 18:13:58 public-server systemd[1]: Failed to start MySQL Server.
2月 03 18:13:59 public-server systemd[1]: Unit mysqld.service entered failed state.
2月 03 18:13:59 public-server systemd[1]: mysqld.service failed.
2月 03 18:14:00 public-server systemd[1]: mysqld.service holdoff time over, scheduling restart.
2月 03 18:14:00 public-server systemd[1]: Stopped MySQL Server.
エラーに関しては、「code=exited status=1」というログのみ。
これで検索しても今回の問題とは関係なさそうな原因しか見当たりません。
うーん、かなり困りました。
しばらくあれやこれやと試したのですが、問題解決に至らず。
打つ手がなくなったので、journalctlをフィルタリング無しで実行してみることに。
すると、次のようなエラーが出てきました。
2月 03 18:46:17 public-server kernel: Out of memory: Kill process 25450 (mysqld) score 81 or sacrifice child
ほうほう、メモリ不足とな。topで使用率を確認したところ、確かに不足していそうです。
そこで、不要なプロセスをキル。その後、mysqld を再起動すると、見事起動しました！
起動しないのは mysqld だけど、起動させなくしているのは kernel でした。
原因が mysqld にあると思いこんでいたばっかりに苦労してしまったというわけでした。
学んだこと
- journalctl という、システムログを確認するコマンドがある
- 思い込みによってログを見逃してしまう事がある。全体ログを見ることも重要