日々の覚書: Mroongaのロックが突き刺さるとどうなるか

むるーん、ｶﾞｯ（挨拶
このエントリーは全文検索エンジンGroonga Advent Calendar 2013 の20日目です。

みなさん、最近、ロック刺さりましたか？
クラッシュ以外でそうそう刺さることはないと思うんですが、いざ刺さるとどうなるのか…というのは予め考えておいた方が良いと思います（こんなエントリーを書いている時点でお察しください）

復旧作業については @yoshi_kenさんの Y-Ken Studio: groonga/mroongaの.mrnファイルがlock failedとなった場合の復旧方法が詳しいですのでそちらで。

クラッシュして刺さるなら、クラッシュした時点で諸々通知されたりサービスから切り離されているので、まあそんなに困りはしないんですが、*何故かクラッシュせずに刺さってしまった場合* の動きは(当然)かなりシビアなものになります。

mysql> SHOW CREATE TABLE t1\G
*************************** 1. row ***************************
       Table: t1
Create Table: CREATE TABLE `t1` (
  `num` int(10) unsigned NOT NULL,
  `val` varchar(32) NOT NULL,
  PRIMARY KEY (`num`),
  FULLTEXT KEY `val` (`val`)
) ENGINE=mroonga DEFAULT CHARSET=utf8
1 row in set (0.02 sec)

mysql> SELECT * FROM t1;
+-----+-----+
| num | val |
+-----+-----+
|   1 | one |
|   2 | two |
+-----+-----+
2 rows in set (0.02 sec)

まあ、こんなテーブルを作るわけです。

ロックの刺し方(どのプロセスも触っていないのに、mrnファイルがロックされたまま解放されない状態の作り方)はすとーさんにTwitterで教えてもらいました。

@yoku0825 あ、Rroongaを使ってもいいなら、require "groonga"; Groonga::Database.open("/DB/PATH"); Groonga["TABLE_NAME"].lock; exitでロック残留させられます！
— す (@ktou) 2013, 12月 17

$ /usr/ruby/2.0.0/bin/ruby -e 'require "groonga"; Groonga::Database.open("/usr/local/mysql/data/d1.mrn"); Groonga["t1"].lock; exit'

と、こう刺してやると、

mysql> SELECT * FROM t1;
+-----+-----+
| num | val |
+-----+-----+
|   1 | one |
|   2 | two |
+-----+-----+
2 rows in set (0.00 sec)

mysql>
mysql> DELETE FROM t1 WHERE num= 1;

SELECTはできるけど、DELETEは返ってこなくなります。
これは良い。別に良い。想定通りの動作です。
困る(?)のはここから後。

mysql> SELECT @@global.lock_wait_timeout;
+----------------------------+
| @@global.lock_wait_timeout |
+----------------------------+
|                          1 |
+----------------------------+
1 row in set (0.00 sec)

mysql> SHOW PROCESSLIST;
+----+------+-----------+------+---------+------+----------+-----------------------------+
| Id | User | Host      | db   | Command | Time | State    | Info                        |
+----+------+-----------+------+---------+------+----------+-----------------------------+
|  3 | root | localhost | d1   | Query   |   63 | updating | DELETE FROM t1 WHERE num= 1 |
|  4 | root | localhost | d1   | Query   |    0 | init     | SHOW PROCESSLIST            |
+----+------+-----------+------+---------+------+----------+-----------------------------+
2 rows in set (0.00 sec)

実際ロックが競合してはいるんですが、lock_wait_timeoutは効きません。SHOW PROCESSLISTを見てやると、Stateはupdatingで、Lock待ち扱いではないですね。ちょっとgdbで覗いてみます。

$ gdb -p `pidof mysqld`
..
(gdb) thread apply all bt
..
Thread 3 (Thread 0x7fb2000be700 (LWP 8370)):
#0  0x0000003eb480ed2d in nanosleep () at ../sysdeps/unix/syscall-template.S:82
#1  0x00007fb200645f79 in grn_nanosleep (nanoseconds=) at ctx.c:81
#2  0x00007fb20074bc72 in grn_io_lock (ctx=0x7fb17400fb38, io=0x7fb17402b0c0, timeout=10000000) at io.c:1320
#3  0x00007fb20066df80 in grn_table_delete_by_id (ctx=0x7fb17400fb38, table=0x7fb17402adf0, id=1) at db.c:1784
#4  0x00007fb1e38ea422 in ha_mroonga::storage_delete_row (this=0x7fb17400e9e0, buf=0x7fb1740379f0 "\001")
    at ha_mroonga.cpp:6241
#5  0x0000000000590460 in handler::ha_delete_row (this=0x7fb17400e9e0, buf=0x7fb1740379f0 "\001")
    at /home/yoku0825/mysql-5.6.15/sql/handler.cc:7281
#6  0x0000000000823ebb in mysql_delete (thd=0x46a4ec0, table_list=0x7fb174005038, conds=0x7fb174005b58,
    order_list=, limit=18446744073709551615, options=0)
    at /home/yoku0825/mysql-5.6.15/sql/sql_delete.cc:373
#7  0x00000000006d5c4a in mysql_execute_command (thd=0x46a4ec0) at /home/yoku0825/mysql-5.6.15/sql/sql_parse.cc:3571
#8  0x00000000006d8607 in mysql_parse (thd=0x46a4ec0, rawbuf=, length=,
    parser_state=) at /home/yoku0825/mysql-5.6.15/sql/sql_parse.cc:6247
#9  0x00000000006d9db3 in dispatch_command (command=COM_QUERY, thd=0x46a4ec0, packet=0x7fb2000bdaf0 "\300Nj\004",
    packet_length=27) at /home/yoku0825/mysql-5.6.15/sql/sql_parse.cc:1334
#10 0x00000000006a23ed in do_handle_one_connection (thd_arg=)
    at /home/yoku0825/mysql-5.6.15/sql/sql_connect.cc:982
#11 0x00000000006a2522 in handle_one_connection (arg=)
    at /home/yoku0825/mysql-5.6.15/sql/sql_connect.cc:898
#12 0x0000000000972a37 in pfs_spawn_thread (arg=0x4766040) at /home/yoku0825/mysql-5.6.15/storage/perfschema/pfs.cc:1858
#13 0x0000003eb4807851 in start_thread (arg=0x7fb2000be700) at pthread_create.c:301
#14 0x0000003eb40e894d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:115
..

grn_io_lockがgrn_nanosleepを呼んでいるので、まあこの辺りですよね。
grn_io_lockはGroonga(not Mroonga)のlib/io.c に実装されています。

1290 grn_io_lock(grn_ctx *ctx, grn_io *io, int timeout)
1291 {
..
1296 for (count = 0;; count++) {
..
1306 if (!timeout || (timeout > 0 && timeout == count)) {
1307 GRN_LOG(ctx, GRN_LOG_WARNING,
1308 "[DB Locked] time out(%d): io(%s) collisions(%d/%d)",
1309 timeout, io->path, _ncolls, _ncalls);
1310 break;
1311 }
..
1320 grn_nanosleep(1000000);
1321 continue;
1322 }
..
1327 }

タイムアウトするまで自前でループしています。mysqld的にはMroongaストレージエンジンが勝手にループしているだけでロックを検知することができませんので、StateはLockedにはならず、Lock wait timeout exceededも起こりません(´・ω・`)

で、コイツがタイムアウトしてくれるまでが長い。

grn_nanosleep(1000000)なので、1回のスリープは1ms。timeoutはgrn_io_lockの呼び出し元すべてで10000000がハードコードされているので、10,000s。

…いちまんびょう？ 3時間？；

GroongaのRedmineにも上がってるけど、長いし変更できないのはつらい。
取り敢えずゴニョゴニョしてtimeoutを1000msに変更してみる。

mysql> INSERT INTO t1 VALUES (1, 'one');
ERROR 1026 (HY000): grn_io_lock failed

$ perror 1026
MySQL error code 1026 (ER_ERROR_ON_WRITE): Error writing file '%-.200s' (errno: %d - %s)

$ less groonga.log
2013-12-19 18:04:52.165728|n|120c6700|io(d1.mrn.0000100) collisions(1000/117): lock failed 1000 times
2013-12-19 18:04:52.165901|w|120c6700|[DB Locked] time out(1000): io(d1.mrn.0000100) collisions(1000/117)
2013-12-19 18:04:52.165917|e|120c6700|grn_io_lock failed
..

うん、やっぱりこれ自分で設定したいなぁ。。（ﾁﾗｯﾁﾗｯ
欲を言えばmy.cnfで設定したいし、更に言うならMySQLのlog-errorにも吐いてほしい。

同じくラッパーモード。

mysql> SHOW CREATE TABLE t1\G
*************************** 1. row ***************************
       Table: t1
Create Table: CREATE TABLE `t1` (
  `num` int(10) unsigned NOT NULL,
  `val` varchar(32) NOT NULL,
  PRIMARY KEY (`num`),
  FULLTEXT KEY `val` (`val`)
) ENGINE=mroonga DEFAULT CHARSET=utf8 COMMENT='engine "innodb"'
1 row in set (0.00 sec)

$ /usr/ruby/2.0.0/bin/ruby -e 'require "groonga"; Groonga::Database.open("/usr/local/mysql/data/d2.mrn"); Groonga["t1"].lock; exit'

mysql> SELECT * FROM t1;
+-----+-----+
| num | val |
+-----+-----+
|   1 | one |
|   2 | two |
+-----+-----+
2 rows in set (0.00 sec)

mysql> DELETE FROM t1 WHERE num= 1;

$ gdb -p `pidof mysqld`
..
(gdb) thread apply all bt
..
Thread 2 (Thread 0x7fd1a009d700 (LWP 16797)):
#0  0x0000003eb480ed2d in nanosleep () at ../sysdeps/unix/syscall-template.S:82
#1  0x00007fd20c481f79 in grn_nanosleep (nanoseconds=) at ctx.c:81
#2  0x00007fd20c587c72 in grn_io_lock (ctx=0x7fd17c012a18, io=0x7fd17c310200, timeout=10000000) at io.c:1320
#3  0x00007fd20c4a9f80 in grn_table_delete_by_id (ctx=0x7fd17c012a18, table=0x7fd17c330ae0, id=1) at db.c:1784
#4  0x00007fd1ed583422 in ha_mroonga::storage_delete_row (this=0x7fd17c0118c0, buf=0x7fd17c038a80 "\001")
    at ha_mroonga.cpp:6241
#5  0x0000000000590460 in handler::ha_delete_row (this=0x7fd17c0118c0, buf=0x7fd17c038a80 "\001")
    at /home/yoku0825/mysql-5.6.15/sql/handler.cc:7281
#6  0x0000000000823ebb in mysql_delete (thd=0x44a0910, table_list=0x7fd17c005038, conds=0x7fd17c005b58, 
    order_list=, limit=18446744073709551615, options=0)
    at /home/yoku0825/mysql-5.6.15/sql/sql_delete.cc:373
#7  0x00000000006d5c4a in mysql_execute_command (thd=0x44a0910) at /home/yoku0825/mysql-5.6.15/sql/sql_parse.cc:3571
#8  0x00000000006d8607 in mysql_parse (thd=0x44a0910, rawbuf=, length=, 
    parser_state=) at /home/yoku0825/mysql-5.6.15/sql/sql_parse.cc:6247
#9  0x00000000006d9db3 in dispatch_command (command=COM_QUERY, thd=0x44a0910, packet=0x7fd1a009caf0 "\020\tJ\004", 
    packet_length=27) at /home/yoku0825/mysql-5.6.15/sql/sql_parse.cc:1334
#10 0x00000000006a23ed in do_handle_one_connection (thd_arg=)
    at /home/yoku0825/mysql-5.6.15/sql/sql_connect.cc:982
#11 0x00000000006a2522 in handle_one_connection (arg=)
    at /home/yoku0825/mysql-5.6.15/sql/sql_connect.cc:898
#12 0x0000000000972a37 in pfs_spawn_thread (arg=0x45619d0) at /home/yoku0825/mysql-5.6.15/storage/perfschema/pfs.cc:1858
#13 0x0000003eb4807851 in start_thread (arg=0x7fd1a009d700) at pthread_create.c:301
#14 0x0000003eb40e894d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:115

全く同じところで突き刺さる。
これ、ラッパーモードだろうと更新であればmrnファイルは常に並列性が無くて、ただ mrnファイルはトランザクションのコミットに関わらず先行して更新が終わってしまうからこのジャイアントロックが問題になることは無くて…というシナリオなんだろう、きっと、たぶん(あるいは、ほんのり問題にはなっているけどそれに気付かないか)

で、mrnファイルのロックが突き刺さると更新系のクエリーが全てupdatingとかexecuteで自前ループを回し、connectionがどんどん溜まりそいつらも自前でループし、最終的にCPUを振り切って略…となったることが予想されるので、タイムアウト値は短めに設定して、groonga.logかアプリのログを監視しておいた方が良いかも。

別にしょっちゅうロックが刺さっててGroongaなんとかしる、という訳ではなく、たまたま刺さった時に大変~~だった~~そうなので備えておきましょうね、というお話でした :)

【2014/01/30 12:57】
2014/01/29リリースのMroonga 3.12で、MySQLのSET GLOBALで動的にタイムアウト閾値を変えられるようになりました！(need Groonga >= 3.1.2)

ありがとうございます！

日々の覚書

GA

2013/12/20

Mroongaのロックが突き刺さるとどうなるか

0 件のコメント :

コメントを投稿