InnoDB の mutex の話（入門編）
sejimaこのエントリは GREE Advent Calendar 2015 22日目の記事です。
こんにちわ。せじまです。久々に 10inch の Android Tablet 買いかえたところ、USBがキャップレス防水になってるわお風呂で使っても内蔵スピーカーでそこそこ音量取れるわ水滴ついた状態でもタッチパネルの精度が高いわと、この分野に於ける技術の進歩ハンパないなと感心させられました。
はじめに
最近、 InnoDB の mutex 周りの実装に関心があるのですが、ちょっと調べてみたところ、自分が読みたいような内容の入門記事が、英語や日本語の blog などでは見つけられなかった、あるいは最近の記事ではなかったので、備忘録を兼ねて自分で書いてみることにしました。今回のゴールは、 SHOW ENGINE INNODB STATUS\G での次のセクションを読み解くところまでです。
|
1 2 3 4 5 6 7 8 9 10 11 |
---------- SEMAPHORES ---------- OS WAIT ARRAY INFO: reservation count 7325520 OS WAIT ARRAY INFO: signal count 6522860 Mutex spin waits 37943231, rounds 459507138, OS waits 5431910 RW-shared spins 3088929, rounds 55181480, OS waits 1297446 RW-excl spins 1347928, rounds 27340426, OS waits 281717 Spin rounds per wait: 12.11 mutex, 17.86 RW-shared, 20.28 RW-excl ------------------------ |
ソースコードは読みやすいので MySQL5.6 を前提としますが、 5.7 についても少し触れようと思います。 5.5 は・・・ mutex の競合を気にするようになってきたら、 MySQL のバージョンアップを検討したほうがいいかもしれません。MySQLの中の人もきっとそう言うでしょう。
mutex_spin_wait()
OS WAIT ARRAY INFO はいわゆる sync array と呼ばれるものについての情報なんですが、とりあえずこの部分は後回しにして、 次の行から見ていきましょう。
|
1 2 |
Mutex spin waits 37943231, rounds 459507138, OS waits 5431910 |
先ずはソースコードを開いてみます。
sync_print_wait_info()を読むと、mutex_spin_round_count,mutex_spin_wait_count,mutex_os_wait_count はそれぞれ、 ib_counter_t class の変数であり、 mutex_spin_wait() で加算されるようです。
※ちなみに、 ib_count_t はある程度マルチスレッド環境を想定したコードになってると思うのですが、 MySQL5.5 のとき mutex_spin_wait_count などはただの static な 64bit の整数型であり、複数のスレッドから同時に更新されていたので、かなり適当な値になってた気がします。 ib_count_t も値が正確になるわけではないのですが、 CPU のキャッシュラインを意識した最適化が施されています。
では、次に mutex_spin_wait() を眺めてみましょう。
ざっとまとめると
- mutex_spin_wait() が呼ばれたら、なにはともあれ mutex_spin_wait_count が加算される。つまり、 Mutex spin waits は mutex_spin_wait() が呼ばれた回数である
- mutex_spin_wait() は spin と mutex の二段構えであり、それでもmutexが取れなかったときに sync array で event を待つ（MySQLの実装的にいうと、条件変数を待ってる）
- mutex に紐付いた lockword が 0 のとき、その mutex を使ってるスレッドはいない（mutexは開放されている）という実装なので、 mutex 取得する前にmutex_get_lock_word() で lockword を取得し、 0 かどうかテストする。
- lockword が 0 になるのを監視する spin loop が、SYNC_SPIN_ROUNDS（具体的には innodb_sync_spin_loops なのでデフォルトだと30回）の数だけ実行される
- spin loop 回った回数だけ mutex_spin_round_count が加算される。つまり、 mutex_spin_round_count は、 spin loop で空振った回数である。
SYNC_SPIN_ROUNDS の回数だけ spin loop 回っても lockword が 0 にならなかった、あるいは他のスレッドに mutex 取られてしまった場合、最大４回 mutex の取得を試みる。 - それでも mutex が取得できなかった場合、 mutex_os_wait_count を +1 して、 sync_array_event_wait() を実行して、条件変数書き換わるのを待つ。つまり、 mutex_os_wait_count は sync_array_event_wait() が mutex_spin_wait() の中で呼ばれた回数である。
- sync_array_event_wait() から return したら、 spin loop からやり直す
という感じになるのですが、一つ一つ見ていきましょう。
※便宜上 mutex と言いましたが、 Test-and-Set命令を使える環境では、 mutex_spin_wait() では pthread_mutex_trylock() のかわりにTASを使うようです。まぁざっくり「同期をとってる」くらいの理解でも大丈夫だと思います。
なぜ spin loop が必要なのか
spin loop（いわゆるspinlock）というものは特に珍しいものではなく、OSの内部で使われているものですが、そのへんの経緯はコメントで書いてあります
忙しい人のために三行でまとめると
- mutex はメモリに対するアトミックな書き込みと読み込みを必要とする
- spin loop はメモリから読むだけなので（場合によってはCPUのキャッシュから読むだけでいいので） mutex より軽い
- 複数のスレッド（複数のCPUのコア）から、同じmutexにアクセスすると、同じメモリの領域に対してアトミックに読み書きすることになるので、リソース競合するしメモリの帯域も使っちゃうので重い。
といったところかなと思います。ただ、休みなく innodb_sync_spin_loops の回数分ループ回るのももったいないので、
|
1 2 3 4 |
if (srv_spin_wait_delay) { ut_delay(ut_rnd_interval(0, srv_spin_wait_delay)); } |
ut_rnd_internal で（0から innodb_spin_wait_delay の範囲で）実行回数をランダマイズしつつ、次回 lock_word の値をチェックするまであるていどの時間を設けています。 pause 命令を使えるCPUであれば、 ut_delay の中で pause 命令を実行しています。
※pause 命令についてはIntelさんによるこちらの記事を参照してください。
SEMAPHORES セクションの最後に出力されている
|
1 2 |
Spin rounds per wait: 12.11 mutex, 17.86 RW-shared, 20.28 RW-excl |
ここで表示されている mutex は、 mutex_spin_round_count /mutex_spin_wait_count といった値になります。この値が大きければ大きいほど、 spin loop を何回も回ってるってことでしょうから、 そのときは innodb_spin_wait_delay をチューニングする余地があるってことかもしれません。
（ここから先は完全に推測の域を出ないのですが） MySQL Performance Architect の DimitriK が公開する資料では、よく
|
1 2 |
innodb_spin_wait_delay = 96 |
という意味不明すぎる謎の数字が出てくるのですが、ひょっとしたら、innodb_spin_wait_delay のデフォルトが 6 なので、DimitriK の実行しているベンチマークと環境の組み合わせだと、
|
1 |
Spin rounds per wait >= (96 / 6) |
という感じで、 Spin rounds per wait が 16 を超えてるのかもしれませんね。
sync array と Thundering herd problem
ベストケースは、 mutex_spin_round_count も mutex_os_wait_count も加算されないケース、mutex_spin_wait_count のみが加算されるケースです。そのとき、 mutex の競合は発生していません。しかし、 mutex_os_wait_count がまったく加算されないってことは、そうそうないでしょう。では、 sync_array_event_wait() では何が行われているのでしょうか。
InnoDB のソースコードはなかなか親切で、 sync array （WAIT ARRAY）についても長文のコメントでちゃんと解説がされています。
これも忙しい人のために三行でまとめると
- 古の windows などはOSの制限が厳しかった
- OSの同期機構だけで同期機構を実現するのは難しかったので、ラッパーとして sync array なるものが作られた
- 現在では、 InnoDB内部でハングアップを検出するために、 error monitor thread が監視するために sync array(wait array) が使われている
とのことです。 SHOW ENGINE INNODB STATUS\G でいうと
|
1 2 3 |
OS WAIT ARRAY INFO: reservation count 7325520 OS WAIT ARRAY INFO: signal count 6522860 |
ここの部分ですね。では、何をやったら reservation count が増えて何をやったら signal count が増えるかですが。
※ mutex 待ってる thread がいると reservation count の行と signal count の行の間にいろいろ表示されるんですがそれについてはまた後ほど
reservation count ですが、これは sync_array_event_wait() を呼ぶために sync array から cell を確保するとき（sync_array_reserve_cell()が呼ばれたとき）に加算され、 sync_array_event_wait() でmutexの開放を待ってるスレッドがいるとき、 そのmutexを unlock する度に signal count は加算されます。 reservation count と signal count の差分が大きければ大きいほど、mutexを予約するスレッドとmutexを開放するスレッドの数の差分が多いということなので、一つのmutexを多くのスレッドが取り合ってる競合状態にあるといえるでしょう。
mutex_spin_wait() などで sync_array_event_wait() を呼ぶと、最終的に os_event_wait_low() を呼んで、 os_cond_wait() から最終的に（Linuxでは） pthread_cond_wait() を呼んで待ち続けることになるのですが、待ってるスレッドたちの mutex つかんでたスレッドが mutex を unlock するタイミングで、そのとき pthread_cond_broadcast() で、待ってたスレッドたちをぜんぶ起床します。
そう、 broadcast するのです！待ってたスレッドたちは、すべて spin loop をやりなおしてしまうわけです！その中で選ばれしものだけが mutex を掴み取ることに成功し、また同じように、 mutex を取れなかったスレッドたちは pthread_cond_wait() で待つというループに入ります。いわゆる Thundering herd problem ですね。mutex_os_wait_count がガッと増える状況が、如何にまずそうかおわかりいただけたかと思います。
一応、 RW-shared や RW-excl
説明はしょってしまいましたが、 Mutex 以外にも RW-shared（共有ロック）や RW-excl（排他ロック） というものがありますが、 spin との二段構えであること、それでもロック取れなかったら pthread_cond_wait() という実装なので、 SHOW ENGINE INNODB STATUS\G のRW-shared spins などは、 Mutex spin waits などと同じように見ていただければ、とりあえず問題ないのではないでしょうか。詳細が気になる方は、 sync/sync0rw.cc を読んでみてください。
ではどうしよう
そうはいっても、 spin lock ですべての問題は解決できないでしょうし、なんらかの方法でスレッドに待ってもらうことは必要でしょう。そう考えると、 spin lock で解決できなかった場合、 pthread_cond_wait() で待ってもらうのは無難ではないかと思います。そうなると、起床するスレッドの数が少なくなれば、状況は改善するはずです。起床するスレッドの数を制限するとしたら、次のようなアプローチが考えられます。
- mutex の分割
- InnoDBは伝統的にこの改善を着々とやっている印象。例えば、 MySQL 5.7.8 から追加された innodb_adaptive_hash_index_parts により、 Adaptive Hash Index の latch（mutex） の数を増やすことができます
- 同時実行されるスレッド数を制限
- innodb_thread_concurrency を変更して InnoDB で同時実行されるスレッドの数を制限する
-- デフォルトは 0 で制限がないので、最悪、CPUのコア数より桁違いに多いスレッドが、一つのmutexをめぐって pthread_cond_wait() で待つ可能性があります - thread pool で InnoDB にアクセスできるスレッド数をそもそも制限
-- MySQL Enterprise Edition の Thread Pool Plugin とか
-- Amazon Aurora も ThreadPool 工夫してるそうなので、このアプローチなんでしょうね
- innodb_thread_concurrency を変更して InnoDB で同時実行されるスレッドの数を制限する
- アプリケーションサーバでコネクションプーリングし、MySQLに張れるコネクションの数を制限
- 例えばJavaだとやりやすいでしょうね
- SQLやtableの設計を見直して、 mutex の競合を削減
secondary index の更新が競合するケースなど、入り口をどんなに絞っても改善しないケースはありえるでしょう。そうなるとやはり、 SQLやtableを見直すというのが、一番無難なところといえるでしょう。
SQLを見直すために
何の情報もない状況でSQLを最適化するというのもつらい話です。できれば何かモニタリングして、ヒントを得たいところです。ここで、 SHOW ENGINE INNODB STATUS\G に出力されている情報が役に立ちます。（ performance_schema & SYS Schema でもいろいろ分かりそうですが、今回はとりあえず SHOW ENGINE INNODB STATUS で）
試しに sysbench 走らせてる最中、次のコマンドを実行すると
|
1 2 |
$ mysql -e 'show engine innodb status\G' | egrep -e '^Mutex at' -e 'Last time.*locked |
次のような情報が得られます。
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 |
$ mysql -e 'show engine innodb status\G' | egrep -e '^Mutex at' -e 'Last time.*locked' Mutex at 0x7f3a78379088 created file lock0lock.cc line 609, lock var 0 Mutex at 0x7f3a78379088 created file lock0lock.cc line 609, lock var 0 Mutex at 0x7f3a78379088 created file lock0lock.cc line 609, lock var 0 Mutex at 0x7f3a78379088 created file lock0lock.cc line 609, lock var 0 Mutex at 0x7f3a78379088 created file lock0lock.cc line 609, lock var 0 Mutex at 0x7f3a78379088 created file lock0lock.cc line 609, lock var 0 Mutex at 0x7f3a78379088 created file lock0lock.cc line 609, lock var 0 Mutex at 0x7f3a78379088 created file lock0lock.cc line 609, lock var 0 Mutex at 0x7f3a78379088 created file lock0lock.cc line 609, lock var 0 Mutex at 0x7f3a78379088 created file lock0lock.cc line 609, lock var 0 Mutex at 0x7f3a78379088 created file lock0lock.cc line 609, lock var 0 Mutex at 0x7f3a78379088 created file lock0lock.cc line 609, lock var 0 Mutex at 0x7f3a78379088 created file lock0lock.cc line 609, lock var 0 Mutex at 0x7f3a78379088 created file lock0lock.cc line 609, lock var 0 Mutex at 0x7f3a78379088 created file lock0lock.cc line 609, lock var 0 Mutex at 0x7f3a78379088 created file lock0lock.cc line 609, lock var 0 Mutex at 0x7f3a78379088 created file lock0lock.cc line 609, lock var 0 Mutex at 0x7f3a78379088 created file lock0lock.cc line 609, lock var 0 Mutex at 0x7f3a78379088 created file lock0lock.cc line 609, lock var 0 Mutex at 0x7f3a78379088 created file lock0lock.cc line 609, lock var 0 Mutex at 0x7f3a78379088 created file lock0lock.cc line 609, lock var 1 Mutex at 0x7f3a78379088 created file lock0lock.cc line 609, lock var 1 Mutex at 0x7f3a78379088 created file lock0lock.cc line 609, lock var 0 Mutex at 0x7f3a78379088 created file lock0lock.cc line 609, lock var 0 Mutex at 0x7f3a78379088 created file lock0lock.cc line 609, lock var 0 Mutex at 0x7f3a78379088 created file lock0lock.cc line 609, lock var 0 Last time read locked in file btr0sea.cc line 931 Last time write locked in file /export/home/pb2/build/sb_0-10831761-1384711588.85/mysql-5.6.15/storage/innobase/row/row0upd.cc line 2391 $ |
ソースコードと行数が特定できるので、どこで mutex や rw_lock を取得してるスレッドが多いのかがわかります。定期的に SHOW ENGINE INNODB STATUS\G して、まずはこれを fluentd などで集めてみるのも良さそうです。
欲をいうと、プロダクション環境でこういった情報を収集してRRDなどに保存し、過去の状況と比較してみたいものです。わたしは以前からこういうメトリックを取得したいと考えていたんですが、ソースコードの行数はMySQLのマイナーバージョン違うだけで変わりうるので、どうしようかなと、かつては思っていました。ただ、「ソースコードが特定できれば、ある程度何をやってるかわかるから別にいいんじゃない？」って割り切ればいいかと最近吹っ切れましたので。
例えばこうします。
|
1 2 3 4 5 6 7 8 9 |
$ mysql -e 'show engine innodb status\G' | egrep -e '^Mutex at' -e 'Last time.*locked' | sed 's/\/.*\///'| sed -e 's/^Last time \([a-z][a-z]*\) locked in file \([a-z0-9][_a-z0-9]*\)\.[chi].*/my_\1_locked_\2/' -e 's/^Last time \([a-z][_a-z]*\) locked in file not yet.*/my_\1_locked_not_yet/' -e 's/^Mutex at.*created file \([a-z0-9][_a-z0-9]*\)\.[chi].*/my_mutex_\1/' | sort | uniq -c 19 my_read_locked_btr0sea 3 my_read_locked_row0sel 4 my_write_locked_btr0sea 1 my_write_locked_row0ins 3 my_write_locked_row0purge 14 my_write_locked_row0upd $ |
これならRRDかなにかに保存できそうです。 row0sel.cc は SELECT、row0ins.cc は INSERT row0upd.cc は UPDATE（あるいはDELETE） 、 row0purge.cc は（InnoDBの内部的な）purge、 btr0sea.cc はAdaptive Hash Index だと、それぞれのソースコードの先頭にあるコメントなど読むと読み取れます。というわけで、上の例でいうと「INSERT/UPDATE（あるいはDELETE）/SELECTを実行中なのだが、 Adaptive Hash Index の mutex が競合してるのかもしれない」という見当がつけられるのではないでしょうか。ここまで具体化できると、実行されているSQLを眺めながら「インデックスの更新が競合してるんだろうか？」と考えたり、グーグル先生にお伺いを立てることもやりやすくなると思います。
ざっくり集計対象となりそうなファイル名を grep などして抽出してみましたが、
5.6 だと 71
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 |
$ find . -type f | xargs egrep -l '(mutex_(create|enter)|rw_lock_create|rw_lock_(s|x|sx)_lock(|_inline|_gen|_gen_nowait|_nowait)\()' | sed 's#./[a-z]*/\([0_a-z]*\)\..*#\1#' | sort | uniq | wc -l 71 $ find . -type f | xargs egrep -l '(mutex_(create|enter)|rw_lock_create|rw_lock_(s|x|sx)_lock(|_inline|_gen|_gen_nowait|_nowait)\()' | sed 's#./[a-z]*/\([0_a-z]*\)\..*#\1#' | sort | uniq | head api0api btr0btr btr0cur btr0sea buf0buddy buf0buf buf0dblwr buf0dump buf0flu buf0lru $ |
5.7だと73あるようなので
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 |
$ find . -type f | xargs egrep -l '(mutex_(create|enter)|rw_lock_create|rw_lock_(s|x|sx)_lock(|_inline|_gen|_gen_nowait|_nowait)\()' | sed 's#./[a-z]*/\([0_a-z]*\)\..*#\1#' | sort | uniq | wc -l 73 $ find . -type f | xargs egrep -l '(mutex_(create|enter)|rw_lock_create|rw_lock_(s|x|sx)_lock(|_inline|_gen|_gen_nowait|_nowait)\()' | sed 's#./[a-z]*/\([0_a-z]*\)\..*#\1#' | sort | uniq | head api0api btr0btr btr0cur btr0sea buf0buddy buf0buf buf0dblwr buf0dump buf0flu buf0lru $ |
RRDに残す場合、項目絞ったほうがいいかもしれません。まだデータを全然集計できてないのでイメージだけでいうと、まずは
- btr0sea.cc
- buf0buf.cc
- row0{ins,upd,sel}.cc
- trx0rseg.cc
このあたりから取ってみようかなぁとぼんやり考えています。まぁ、ここからさきは入門編ではなく応用編の内容という気もするので、またの機会にさせていただきます。
MySQL5.7 では
SHOW ENGINE INNODB STATUS\G の SEMAPHOES セクションの表示が次のように変わりました。
|
1 2 3 4 5 6 7 8 9 10 11 |
---------- SEMAPHORES ---------- OS WAIT ARRAY INFO: reservation count 27522 OS WAIT ARRAY INFO: signal count 38076 RW-shared spins 0, rounds 33935, OS waits 6577 RW-excl spins 0, rounds 76207, OS waits 2196 RW-sx spins 884, rounds 13659, OS waits 107 Spin rounds per wait: 33935.00 RW-shared, 76207.00 RW-excl, 15.45 RW-sx ------------------------ |
Mutex spin wait の行がなくなり、代わりに RW-sx が追加されました。 SX-lock についての WorkLog はこちらになります。 SX-lock は index->lock の改善 のために必要だったようですね。
Mutex spin wait がなくなってますけど、 5.7 の sync0sync.cc を読んでいただくとわかるのですが、かなりリファクタリングされています。あまり宣伝されてない気がしますけど、WorkLog でいうとこちらのWorkLogですね。
Futex - Only on Linux
This a a TTAS type of mutex that uses Futexes instead of os_event_t to wait when there is contention. The advantage is that we avoid the thundering herd problem by using the Linux futex infrastructure.
素晴らしい！InnoDB 開発チームはかなり地道に改善を続けているようです。
と、おもいきや・・・
event: Use event mutexes. This is the default value and the original InnoDB mutex implementation.
今のところまだ futex は build 時のオプション扱いのようです。 dev.mysql.com から配布するバイナリは、古い環境に配慮しているということでしょうか？早くデフォルトにできる時代が来てほしいものです。
最後に
このあたりで今回の入門編は終わりにさせていただこうと思います。ある程度ノウハウがたまってきたら、応用編かけたらいいなと思ってます。
明日は若手の上竹くんです。お楽しみに！
References
- InnoDB Deep Talk #2 (仮) に引っ張りだされました。
- How to Fulfil the Potential of InnoDB's Performance and Scalability
- SHOW INNODB STATUS walk through
- Internals of InnoDB mutexes
- Slides from my talk about MySQL Performance @OpenWorld 2015
- MySQL Performance: PFS Overhead in 5.6