とあるサイトでDBが落ちたので調査
あるサイトのDBが落ちた。再起動で復旧したが、なぜ落ちたのか？を探っておきたい。DBログは初めて見る。
落ちるまでのログ
xxxxxx xx:12:54 mysqld_safe Number of processes running now: 0
xxxxxx xx:13:10 mysqld_safe mysqld restarted
xxxxxx xx:13:42 [Note] /usr/libexec/mysqld (mysqld 5.5.65-MariaDB) starting as process 22554 ...
xxxxxx xx:53:47 InnoDB: The InnoDB memory heap is disabled
xxxxxx xx:53:47 InnoDB: Mutexes and rw_locks use GCC atomic builtins
xxxxxx xx:53:47 InnoDB: Compressed tables use zlib 1.2.7
xxxxxx xx:53:47 InnoDB: Using Linux native AIO
xxxxxx xx:53:47 InnoDB: Initializing buffer pool, size = 128.0M
InnoDB: mmap(137756672 bytes) failed; errno 12
xxxxxx xx:53:47 InnoDB: Completed initialization of buffer pool
xxxxxx xx:53:47 InnoDB: Fatal error: cannot allocate memory for the buffer pool
xxxxxx xx:53:47 [ERROR] Plugin 'InnoDB' init function returned error.
xxxxxx xx:53:47 [ERROR] Plugin 'InnoDB' registration as a STORAGE ENGINE failed.
xxxxxx xx:53:47 [ERROR] mysqld: Out of memory (Needed 128917504 bytes)
xxxxxx xx:53:48 [Note] Plugin 'FEEDBACK' is disabled.
xxxxxx xx:53:48 [ERROR] Unknown/unsupported storage engine: InnoDB
xxxxxx xx:53:48 [ERROR] Aborting
xxxxxx xx:53:48 [Note] /usr/libexec/mysqld: Shutdown complete
xxxxxx xx:53:50 mysqld_safe mysqld from pid file /var/run/mariadb/mariadb.pid ended
mysqlのログからは追えない（ログの種類と出力方法が複数ある）
直接の原因はメモリ不足だということが解った。なぜメモリ不足が起きたのか？というのが次の問になるが、ここで壁に当たる。
mysqlのエラーログは5タイプあるらしい。しかし、初期設定では1つしか記録されない。残りの4つはそれぞれを有効化しないと記録されない。
これは困った。次回以降は必ず有効化しておこう。
mysqlからの調査はこれ以上できなさそう。なのでApacheログをみる。
Apacheでは特に異常無さそう
ログをざっと見たけれども、問題になりそうなログはなかった。しかし、もしかするとmysqlと同様、違うログファイルもあるのかも知れない。
メモリ使用率を確認してみる
freeコマンドでマシンのメモリ使用率を調べてみると、availableの値が全容量の半分しかない。これはスペックが足りない、という判断で良いのだろうか。
普段からメモリの割当が充分ではないという仮説は一つ立ち上がった。
過去のパフォーマンス指標と照らし合わせてみる
freeコマンドでメモリが充分でなさそうであることはわかった。過去の数値と照らしてみることができれば、突発的な事象であるかどうかは確認できそう。
そこで、過去のパフォーマンス指標を確認したく、検索をする。sarコマンドを使うと過去のパフォーマンス情報が見られるようだ。
確認してみると、やはりダウンしたタイミング（赤文字部分）で異常値がある。ただしこれはCPU使用率を表す数値なので、少し目的と異なっていた。
メモリはどうか。……これも、7日以上残す場合には設定がいるようだ。次回気をつけよう。今回は検証できる。
xx:40:01 CPU %user %nice %system %iowait %steal %idle
xx:10:01 all 3.18 0.00 0.09 0.01 0.16 96.56
xx:20:01 all 2.44 0.00 0.07 0.00 0.06 97.44
xx:30:01 all 4.26 0.00 0.08 0.00 0.11 95.54
xx:40:01 all 5.00 0.00 0.11 0.00 0.16 94.73
xx:50:52 all 12.27 0.00 3.88 22.79 0.64 60.42
xx:00:02 all 2.74 0.00 4.41 79.44 0.76 12.65
xx:10:01 all 2.66 0.00 0.10 0.23 0.12 96.89
xx:20:01 all 4.09 0.00 0.08 0.05 0.18 95.61
xx:30:01 all 4.35 0.00 0.11 0.01 0.19 95.33
xx:40:01 all 4.65 0.00 0.14 0.04 0.30 94.87
/var/log/saの中にはsa日付、sar日付というファイルがある。saではCPU、sarではさらに細かいデータが見られるようなので、試してみる。
cswch/sの値が激増している
発生時のcswch/sという数値が、通常時の20倍以上になっていることがわかった。
cswch/s = 1秒間に発生したコンテキスト切り替えの総数…との記載があったが、詳しいところはよくわからない。CPU使用率が上がるとこの数値も上がるようだ。
pswpin/s pswpoutの数値も激増
こちらは万倍レベルに上昇している。スワップのイン・アウトなので、メモリで抱えきれなくなった分をディスクに逃したりメモリに戻したりしている、ということ。どちらにせよ、オーバーフロー状態であることがわかった。
rd_sec/s wr_sec/sも激増
ここも万倍レベルで上昇。devは一つしかないので、そのデバイスへの書き込み、読み込みが急上昇したことになる。
ネットワーク関連
ネットワーク関連の数値は異常値と言えるものが見当たらなかった。
TCPソケットの数値に異常発見
tcpsckの値が通常時の100倍程度に上昇していた。DOS攻撃の類が濃厚となるのだろうか。
再度apacheログをみてみると、色々探られていることが発覚
行き詰まったので、再度Apacheのログを調べる。じっくり見ていくと、とあるIPからいろいろ探られていることが解った。
ただし、IPは大量ではないため、メモリ不足によるデータベースダウン、ということに落ち着いた。
結論としてどうか、先達に聞いてみたいものだ。身近にいないけど…。
