MySQLがオンラインALTER TABLEでOOM Killerに殺されたはなし
mysql

MySQLがオンラインALTER TABLEでOOM Killerに殺されたはなし

このエントリーをはてなブックマークに追加

こんにちは、DBAです。

MySQL5.6のオンラインALTER TABLEでハマった時のおはなしです。

5.6にはオンラインALTER TABLE関連のパラメーターに innodb_sort_buffer_size というものが追加されており(5.5以前はfast index creationが効く時に使われるパラメーターとして内部的に1Mでハードコードされていたものが、設定可能になった)、前にざっくり試したところ 大きくすれば一応それなりの恩恵は受けられそうなので大きくしたんですよ。

毎日の定期バッチで盛大にInnoDBのテーブルにバルクインサートをかけた後にALTER TABLEでインデックスをくっつけてRENAME TABLEでテーブルを切り替える…なんてことをやっているサービスには打ってつけだと思ったわけです(そもそもそのやり方の善悪について やがて DBAは 考えることを止めた)

innodb_sort_buffer_sizeは再起動が必要なパラメーターなので、計画メンテのついでに設定変更して再起動。innodb_buffer_pool_load_at_startup が有効にしてあるので、MySQLを起動してから数分間でバッファプールが満タンまで充填されます。

この時点で、mysqldの使用メモリーはおよそ23GB(innodb_buffer_pool_size= 20G + αなかんじ)、サーバー全体で積んであるメモリーは48GBで、Free 20Gくらいと残り5Gくらいがバッファキャッシュ(Mroonga使ってるサーバーなので、Mroongaが使うぶんにかなり余裕を持たせてます)

エラーも特に無く、テストもすんなり通り一安心。メンテ用に停止していたバッチを再開。

……そして悲劇が起きました。

14xxxx xx:xx:xx mysqld_safe Number of processes running now: 0
14xxxx xx:xx:xx mysqld_safe mysqld restarted
2014-xx-xx xx:xx:xx 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timest
amp server option (see documentation for more details).
2014-xx-xx xx:xx:xx 3948 [Note] Plugin 'FEDERATED' is disabled.
..

( ゚д゚) ファッ!? エラーログに何も吐かずに再起動したよ!?

$ ll core*
ls: cannot access core*: No such file or directory

coreも吐いてない。

よく訓練されたMySQLerの方ならピンと来るんじゃないかと思うんですが、これってOOM Killerに殺された時の特徴なんですよね

# less /var/log/messages
..
xxx xx xx:xx:xx xxxx kernel: Free swap  = 0kB .. xxx xx xx:xx:xx xxxx kernel: Out of memory: Kill process 21560 (mysqld) score 985 or sacrifice child xxx xx xx:xx:xx xxxx kernel: Killed process 21560, UID 600, (mysqld) total-vm:60118540kB, anon-rss:48632420kB, file-rss:4kB ..

ほらやっぱり! …というかアレ? 何? VSZ 60GにRSS 48Gで更にスワップも食いきった? バッファプールの暖気が終わってからの10分間だけで?

やってたことといえばバッチでALTER TABLEくらいなんだけど…。

( ゚д゚) おや、失敗したバッチのようすが…。

ALTER TABLE table_1 ADD INDEX `idx_col1_col2` (`col_1`, `col_2`),
                    ADD INDEX `idx_col2_col1_col3_col4_col5_col6` (`col_2`, `col_1`, `col_3`, `col_4`, `col_5`, `col_6`),
                    ADD INDEX `idx_col2_col1_col3_col4_col7_col6` (`col_2`, `col_1`, `col_3`, `col_4`, `col_7`, `col_6`),
                    ADD INDEX `idx_col2_col1_col8_col4_col5_col6` (`col_2`, `col_1`, `col_8`, `col_4`, `col_5`, `col_6`),
                    ADD INDEX `idx_col2_col1_col8_col4_col7_col6` (`col_2`, `col_1`, `col_8`, `col_4`, `col_7`, `col_6`),
                    ADD INDEX `idx_col2_col1_col9_col4_col5_col6` (`col_2`, `col_1`, `col_9`, `col_4`, `col_5`, `col_6`),
                    ADD INDEX `idx_col2_col1_col9_col4_col7_col6` (`col_2`, `col_1`, `col_9`, `col_4`, `col_7`, `col_6`),
                    ADD INDEX `idx_col2_col1_col10_col4_col5_col6` (`col_2`, `col_1`, `col_10`, `col_4`, `col_5`, `col_6`),
                    ADD INDEX `idx_col2_col1_col10_col4_col7_col6` (`col_2`, `col_1`, `col_10`, `col_4`, `col_7`, `col_6`),
                    ADD INDEX `idx_col2_col1_col11_col4_col5_col6` (`col_2`, `col_1`, `col_11`, `col_4`, `col_5`, `col_6`),
                    ADD INDEX `idx_col2_col1_col11_col4_col7_col6` (`col_2`, `col_1`, `col_11`, `col_4`, `col_7`, `col_6`),
                    ADD INDEX `idx_col2_col1_col12_col4_col5_col6` (`col_2`, `col_1`, `col_12`, `col_4`, `col_5`, `col_6`),
                    ADD INDEX `idx_col2_col1_col12_col4_col7_col6` (`col_2`, `col_1`, `col_12`, `col_4`, `col_7`, `col_6`),
                    ADD INDEX `idx_col2_col1_col13_col4_col5_col6` (`col_2`, `col_1`, `col_13`, `col_4`, `col_5`, `col_6`),
                    ADD INDEX `idx_col2_col1_col13_col4_col7_col6` (`col_2`, `col_1`, `col_13`, `col_4`, `col_7`, `col_6`)
;

( ゚д゚)

(つд⊂)ゴシゴシ

(;゚д゚)

(つд⊂)ゴシゴシ
  _, ._
(;゚ Д゚)

15インデックス同時追加(しかも、これtable_1~table_7(仮名)くらいまであって、3つずつ並行でALTER TABLEが流れるようにしているらしい。

そして考えるわけです。

innodb_sort_buffer_size= 64M, インデックス1つ作るのに最低この4倍、カラムサイズによってもっと増えるはず, それを15インデックスだから更に15倍、3並列で3倍…"最低この4倍"のレートで計算しても既に11GB。

ああ、食いきってもおかしくないね、うん、おかしくない。

というかこれswap使用率が上がってきたからperformance_schemaを切るのもついでにやってたんですが、swapの原因はp_sだけじゃなくてあなたもいたんですねALTER TABLE。

5.5のFast Index Creationの時点では(1MBでハードコードされていたゆえに)それほど「メモリーを食う動作」としては思っていなかったALTER TABLEが、設定によっては意外とメモリーを(しかも、グローバルバッファでなく個別のバッファとして)食うようになっていました、というお話です。

OOM Killerまで到達することはないはずですが、何かあった時に思い出していただければ幸いです。

( ´-`).oO(そういえばこのサービス、Mroongaのバグも想像を絶する方法でしこたま踏み抜いたんだよなぁ。。

InnoDB開発してる人もまさかこんなALTER TABLEが流れてくるなんて思ってなかったろうし、開発者が想定する範囲から外れた何かをやると、途端に踏み抜く率が上がる気がします。

まずはこのALTER TABLEが「規定外」のモノだとマサカリ 伝道することから始めたいと思います。では。


名無しのエンジニア
新卒2年目がぼっちでGoogle I/Oに行ってきた話(後編)
draperやactive_decoratorを使ってViewに書いてしまったロジックを減らす