2013年12月20日金曜日

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で教えてもらいました。



$ /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)

ありがとうございます!

2013年12月17日火曜日

もしMroongaのWプラグマがなかったら

このエントリーは 全文検索エンジンGroonga Advent Calendar 2013 の17日目です。

2013/05/29リリースの Mroonga 3.04 の新機能として、TritonnにあったWプラグマのバックポート(?)があります。重み付け検索というより、マルチセクションインデックスの一部を使って検索するために使うことが多いような気もします。

mysql> SHOW CREATE TABLE t1\G
*************************** 1. row ***************************
       Table: t1
Create Table: CREATE TABLE `t1` (
  `num` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
  `val1` varchar(20) DEFAULT NULL,
  `val2` varchar(20) DEFAULT NULL,
  `val3` varchar(20) DEFAULT NULL,
  UNIQUE KEY `num` (`num`),
  FULLTEXT KEY `val1` (`val1`,`val2`,`val3`)
) ENGINE=mroonga AUTO_INCREMENT=100002 DEFAULT CHARSET=utf8
1 row in set (0.00 sec)

mysql> SELECT * FROM t1 WHERE MATCH(val1) AGAINST('デコ助' IN BOOLEAN MODE) ORDER BY num LIMIT 3;
ERROR 1191 (HY000): Can't find FULLTEXT index matching the column list

mysql> SELECT * FROM t1 WHERE MATCH(val1, val2, val3) AGAINST('+デコ助' IN BOOLEAN MODE) ORDER BY num LIMIT 3;
+-----+---------------------------------------+--------------------------------------+---------------------------------------------+
| num | val1                                  | val2                                 | val3                                        |
+-----+---------------------------------------+--------------------------------------+---------------------------------------------+
|   5 | アイドルマスター                      | アウトブレイク奇妙な冒険             | 人類はデコ助野郎!                           |
|   9 | 13日のデコ助野郎!                     | 恋と選挙と恋がしたい!                | ジョジョのUC[ユニコーン]                    |
|  14 | アウトブレイクデコ助野郎!             | 魔法少女カンパニー                   | コードギアス亡国の恋がしたい!               |
+-----+---------------------------------------+--------------------------------------+---------------------------------------------+
3 rows in set (0.01 sec)

mysql> SELECT * FROM t1 WHERE MATCH(val1, val2, val3) AGAINST('*W0:1,1:0,2:0 +デコ助' IN BOOLEAN MODE) ORDER BY num LIMIT 3;
+-----+---------------------------------------+---------------------------------+---------------------------------------------+
| num | val1                                  | val2                            | val3                                        |
+-----+---------------------------------------+---------------------------------+---------------------------------------------+
|   9 | 13日のデコ助野郎!                     | 恋と選挙と恋がしたい!           | ジョジョのUC[ユニコーン]                    |
|  14 | アウトブレイクデコ助野郎!             | 魔法少女カンパニー              | コードギアス亡国の恋がしたい!               |
| 115 | インフィニットデコ助野郎!             | 僕は友達が金曜日                | 魔法少女@がんばらない                      |
+-----+---------------------------------------+---------------------------------+---------------------------------------------+
3 rows in set (0.02 sec)

val1からだけ"デコ助"を検索したいのですが、val1だけに張られたフルテキストインデックスは無いので怒られます(1つ目のSELECT)し、かといってMATCH(val1, val2, val3)とするとval1, val2, val3全てから"デコ助"を探してしまいます。Wプラグマがあれば、重み付けでカラム0(=val1)の重みを1に、カラム1(=val2)とカラム2(=val3)の重みを0にしてやることで、val1からだけ検索することができます。

重みも考慮した検索結果を返したいときはORDER BYを併用して

mysql> SELECT *, MATCH(val1, val2, val3) AGAINST('+デコ助' IN BOOLEAN MODE) AS score FROM t1 WHERE MATCH(val1, val2, val3) AGA
INST('+デコ助' IN BOOLEAN MODE)  ORDER BY score DESC, num ASC LIMIT 3;
+-------+---------------------------+---------------------------------------+---------------------------------------+-------+
| num   | val1                      | val2                                  | val3                                  | score |
+-------+---------------------------+---------------------------------------+---------------------------------------+-------+
|  8808 | 13日のデコ助野郎!         | さんをつけろよデコ助野郎!             | さんをつけろよデコ助野郎!             |     3 |
| 10139 | 進撃のデコ助野郎!         | ささみさんデコ助野郎!                 | インフィニットデコ助野郎!             |     3 |
| 12213 | 人類はデコ助野郎!         | 僕は友達がデコ助野郎!                 | アイドルデコ助野郎!                   |     3 |
+-------+---------------------------+---------------------------------------+---------------------------------------+-------+
3 rows in set (0.02 sec)

mysql> SELECT *, MATCH(val1, val2, val3) AGAINST('*W0:2,1:1,2:1 +デコ助' IN BOOLEAN MODE) AS score FROM t1 WHERE MATCH(val1, val2, val3) AGAINST('*W0:2,1:1,2:1 +デコ助' IN BOOLEAN MODE)  ORDER BY score DESC, num LIMIT 3;
+-------+---------------------------+---------------------------------------+---------------------------------------+-------+
| num   | val1                      | val2                                  | val3                                  | score |
+-------+---------------------------+---------------------------------------+---------------------------------------+-------+
|  8808 | 13日のデコ助野郎!         | さんをつけろよデコ助野郎!             | さんをつけろよデコ助野郎!             |     4 |
| 10139 | 進撃のデコ助野郎!         | ささみさんデコ助野郎!                 | インフィニットデコ助野郎!             |     4 |
| 12213 | 人類はデコ助野郎!         | 僕は友達がデコ助野郎!                 | アイドルデコ助野郎!                   |     4 |
+-------+---------------------------+---------------------------------------+---------------------------------------+-------+
3 rows in set (0.03 sec)

スコアが大きい順番に並べてみたりできます。スコアだけでORDER BYしている場合、スコアが同じタプルが存在する場合、どんな順番で返すかは保証されません。たぶん.mrnファイルの内部構造に依存するんだと思います。

全ての重みが均等(Wプラグマの中で重みを指定しなかった場合、全部のカラムが重み1で扱われる)の時のスコアに比べて、val1の重みを2にした時のスコアが上がってます。わかりやすい。

さて、Wプラグマが無かった昔(といっても、半年ちょっと前のことだし、簡単にMroongaをアップグレードする訳にいかない人たちは今なお)、重み付け検索をするにはどうすれば良かったんだろうという *思考実験* です。

mysql> SHOW CREATE TABLE t1\G
*************************** 1. row ***************************
       Table: t1
Create Table: CREATE TABLE `t1` (
  `num` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
  `val1` varchar(20) DEFAULT NULL,
  `val2` varchar(20) DEFAULT NULL,
  `val3` varchar(20) DEFAULT NULL,
  UNIQUE KEY `num` (`num`),
  FULLTEXT KEY `val1` (`val1`),
  FULLTEXT KEY `val2` (`val2`),
  FULLTEXT KEY `val3` (`val3`)
) ENGINE=mroonga AUTO_INCREMENT=100002 DEFAULT CHARSET=utf8
1 row in set (0.00 sec)

mysql> SELECT *, MATCH(val1) AGAINST('+デコ助' IN BOOLEAN MODE)* 2+ MATCH(val2) AGAINST('+デコ助' IN BOOLEAN MODE)+ MATCH(val3) AGAINST('+デコ助' IN BOOLEAN MODE) AS score FROM t1 WHERE MATCH(val1) AGAINST('+デコ助' IN BOOLEAN MODE)* 2+ MATCH(val2) AGAINST('+デコ助' IN BOOLEAN MODE)+ MATCH(val3) AGAINST('+デコ助' IN BOOLEAN MODE) ORDER BY score DESC, num ASC LIMIT 3;
+-------+---------------------------+---------------------------------------+---------------------------------------+-------+
| num   | val1                      | val2                                  | val3                                  | score |
+-------+---------------------------+---------------------------------------+---------------------------------------+-------+
|  8808 | 13日のデコ助野郎!         | さんをつけろよデコ助野郎!             | さんをつけろよデコ助野郎!             |     4 |
| 10139 | 進撃のデコ助野郎!         | ささみさんデコ助野郎!                 | インフィニットデコ助野郎!             |     4 |
| 12213 | 人類はデコ助野郎!         | 僕は友達がデコ助野郎!                 | アイドルデコ助野郎!                   |     4 |
+-------+---------------------------+---------------------------------------+---------------------------------------+-------+
3 rows in set (0.33 sec)

クエリーが見にくい上に重い。。容量効率も悪そうですが、他にぱっと思い付きませんでした。
プロファイルの結果はこんなかんじ(Warningが出てるのは5.6では@@profileはdeprecatedだよってアレ)

mysql> SHOW PROFILE FOR QUERY 54;
+--------------------------------+----------+
| Status                         | Duration |
+--------------------------------+----------+
| starting                       | 0.000037 |
| Waiting for query cache lock   | 0.000005 |
| init                           | 0.000004 |
| checking query cache for query | 0.000164 |
| checking permissions           | 0.000011 |
| Opening tables                 | 0.000042 |
| init                           | 0.000063 |
| System lock                    | 0.000043 |
| Waiting for query cache lock   | 0.000004 |
| System lock                    | 0.000031 |
| optimizing                     | 0.000017 |
| statistics                     | 0.000365 |
| preparing                      | 0.000027 |
| FULLTEXT initialization        | 0.020383 |
| Sorting result                 | 0.000022 |
| executing                      | 0.000005 |
| Sending data                   | 0.000018 |
| Creating sort index            | 0.302915 |
| end                            | 0.000026 |
| query end                      | 0.000008 |
| closing tables                 | 0.000212 |
| freeing items                  | 0.000355 |
| Waiting for query cache lock   | 0.000007 |
| freeing items                  | 0.000350 |
| Waiting for query cache lock   | 0.000006 |
| freeing items                  | 0.000004 |
| storing result in query cache  | 0.000006 |
| cleaning up                    | 0.000034 |
+--------------------------------+----------+
28 rows in set, 1 warning (0.01 sec)

mysql> explain SELECT *, MATCH(val1) AGAINST('+デコ助' IN BOOLEAN MODE)* 2+ MATCH(val2) AGAINST('+デコ助' IN BOOLEAN MODE)+ MATCH(val3) AGAINST('+デコ助' IN BOOLEAN MODE) AS score FROM t1 WHERE MATCH(val1) AGAINST('+デコ助' IN BOOLEAN MODE)* 2+ MATCH(val2) AGAINST('+デコ助' IN BOOLEAN MODE)+ MATCH(val3) AGAINST('+デコ助' IN BOOLEAN MODE) ORDER BY score DESC, num ASC LIMIT 3;
+----+-------------+-------+------+---------------+------+---------+------+--------+-----------------------------+
| id | select_type | table | type | possible_keys | key  | key_len | ref  | rows   | Extra                       |
+----+-------------+-------+------+---------------+------+---------+------+--------+-----------------------------+
|  1 | SIMPLE      | t1    | ALL  | NULL          | NULL | NULL    | NULL | 100001 | Using where; Using filesort |
+----+-------------+-------+------+---------------+------+---------+------+--------+-----------------------------+
1 row in set (0.00 sec)

EXPLAINがALLになっちゃった(´・ω・`) ほんとかな。
こっちがWプラグマでさっくりやった時のプロファイル。

mysql> show profile;
+--------------------------------+----------+
| Status                         | Duration |
+--------------------------------+----------+
| starting                       | 0.000039 |
| Waiting for query cache lock   | 0.000004 |
| init                           | 0.000004 |
| checking query cache for query | 0.000135 |
| checking permissions           | 0.000011 |
| Opening tables                 | 0.000041 |
| init                           | 0.000068 |
| System lock                    | 0.000020 |
| Waiting for query cache lock   | 0.000003 |
| System lock                    | 0.000024 |
| optimizing                     | 0.000017 |
| statistics                     | 0.000423 |
| preparing                      | 0.000028 |
| FULLTEXT initialization        | 0.018467 |
| Sorting result                 | 0.000028 |
| executing                      | 0.000005 |
| Sending data                   | 0.000024 |
| Creating sort index            | 0.000195 |
| end                            | 0.000010 |
| query end                      | 0.000010 |
| closing tables                 | 0.000184 |
| freeing items                  | 0.000178 |
| Waiting for query cache lock   | 0.000006 |
| freeing items                  | 0.000315 |
| Waiting for query cache lock   | 0.000006 |
| freeing items                  | 0.000003 |
| storing result in query cache  | 0.000006 |
| cleaning up                    | 0.000037 |
+--------------------------------+----------+
28 rows in set, 1 warning (0.00 sec)

mysql> explain SELECT *, MATCH(val1, val2, val3) AGAINST('*W0:2,1:1,2:1 +デコ助' IN BOOLEAN MODE) AS score FROM t1 WHERE MATCH(val1, val2, val3) AGAINST('*W0:2,1:1,2:1 +デコ助' IN BOOLEAN MODE)  ORDER BY score DESC, num ASC LIMIT 3;
+----+-------------+-------+----------+---------------+------+---------+------+------+---------------------------------------------------+
| id | select_type | table | type     | possible_keys | key  | key_len | ref  | rows | Extra                                             |
+----+-------------+-------+----------+---------------+------+---------+------+------+---------------------------------------------------+
|  1 | SIMPLE      | t1    | fulltext | val1          | val1 | 0       | NULL |    1 | Using where with pushed condition; Using filesort |
+----+-------------+-------+----------+---------------+------+---------+------+------+---------------------------------------------------+
1 row in set (0.00 sec)

意外なのは、FULLTEXT initやfreeing itemsはそこまで盛大に時間がかかる訳じゃなく、ソートの部分(Creating sort index)でのみ大きく差が出ていること。

mysql> SELECT *, MATCH(val1, val2, val3) AGAINST('+デコ助' IN BOOLEAN MODE)+ (val1 LIKE '%デコ助%') AS score FROM t1 WHERE MATCH(val1, val2, val3) AGAINST('+デコ助' IN BOOLEAN MODE) ORDER BY score DESC, num ASC LIMIT 3;
+-------+---------------------------+---------------------------------------+---------------------------------------+-------+
| num   | val1                      | val2                                  | val3                                  | score |
+-------+---------------------------+---------------------------------------+---------------------------------------+-------+
|  8808 | 13日のデコ助野郎!         | さんをつけろよデコ助野郎!             | さんをつけろよデコ助野郎!             |     4 |
| 10139 | 進撃のデコ助野郎!         | ささみさんデコ助野郎!                 | インフィニットデコ助野郎!             |     4 |
| 12213 | 人類はデコ助野郎!         | 僕は友達がデコ助野郎!                 | アイドルデコ助野郎!                   |     4 |
+-------+---------------------------+---------------------------------------+---------------------------------------+-------+
3 rows in set (0.09 sec)

mysql> explain SELECT *, MATCH(val1, val2, val3) AGAINST('+デコ助' IN BOOLEAN MODE)+ (val1 LIKE '%デコ助%') AS score FROM t1 WHERE MATCH(val1, val2, val3) AGAINST('+デコ助' IN BOOLEAN MODE) ORDER BY score DESC, num ASC LIMIT 3;
+----+-------------+-------+----------+---------------+------+---------+------+------+---------------------------------------------------+
| id | select_type | table | type     | possible_keys | key  | key_len | ref  | rows | Extra                                             |
+----+-------------+-------+----------+---------------+------+---------+------+------+---------------------------------------------------+
|  1 | SIMPLE      | t1    | fulltext | val1          | val1 | 0       | NULL |    1 | Using where with pushed condition; Using filesort |
+----+-------------+-------+----------+---------------+------+---------+------+------+---------------------------------------------------+
1 row in set (0.00 sec)

mysql> SHOW PROFILE FOR QUERY 77;
+--------------------------------+----------+
| Status                         | Duration |
+--------------------------------+----------+
| starting                       | 0.000055 |
| Waiting for query cache lock   | 0.000005 |
| init                           | 0.000004 |
| checking query cache for query | 0.000141 |
| checking permissions           | 0.000011 |
| Opening tables                 | 0.000043 |
| init                           | 0.000070 |
| System lock                    | 0.000019 |
| Waiting for query cache lock   | 0.000003 |
| System lock                    | 0.000018 |
| optimizing                     | 0.000015 |
| statistics                     | 0.000356 |
| preparing                      | 0.000025 |
| FULLTEXT initialization        | 0.011795 |
| Sorting result                 | 0.000020 |
| executing                      | 0.000004 |
| Sending data                   | 0.000018 |
| Creating sort index            | 0.075364 |
| end                            | 0.000023 |
| query end                      | 0.000009 |
| closing tables                 | 0.000201 |
| freeing items                  | 0.000181 |
| Waiting for query cache lock   | 0.000006 |
| freeing items                  | 0.000318 |
| Waiting for query cache lock   | 0.000006 |
| freeing items                  | 0.000002 |
| storing result in query cache  | 0.000007 |
| cleaning up                    | 0.000033 |
+--------------------------------+----------+
28 rows in set, 1 warning (0.00 sec)

重みをつけるカラムが大したことない数の場合は、(val1 LIKE '%..%')で無理矢理重みをつけてしまう(LIKE句にマッチした場合は1, マッチしない場合は0が戻るので、掛け算なり足し算なりある程度スコアとして使える)
こっちの方がまだマシそうな速度。。ただしクエリーはいやんな感じだなあ。。

やっぱりおとなしく最新のMroonga使うべきですね! :)

ちなみに、テストデータは MySQL Casual Advent Calendar 2013 の13日目、 @meijikさん の テストデータ作成時に便利なストアドファンクション で作りました :)


明日は @ongaeshiさん の2回目です! :)

2013年12月14日土曜日

wsrep_sst_authでハマったメモ

Percona XtraDB Clusterでクラスターの初期化中に、

wsrep_sst_method= xtrabackup
wsrep_sst_auth= username:password
としてても、JOINER側で

131212 17:22:05 [Note] WSREP: State transfer required:
        Group state: 64863b36-62f7-11e3-bef2-a746941be182:1
        Local state: 00000000-0000-0000-0000-000000000000:-1
131212 17:22:05 [Note] WSREP: New cluster view: global state: 64863b36-62f7-11e3-bef2-a746941be182:1, view# 10: Primary, numbe
r of nodes: 2, my index: 1, protocol version 2
131212 17:22:05 [Warning] WSREP: Gap in state sequence. Need state transfer.
131212 17:22:07 [Note] WSREP: Running: 'wsrep_sst_xtrabackup --role 'joiner' --address '192.168.xxx.xxx' --auth '' --datadir '/xxx' --defaults-file '/xxx/my.cnf' --parent '3382''
WSREP_SST: [INFO] Streaming with tar (20131212 17:22:08.058)
WSREP_SST: [INFO] Using socat as streamer (20131212 17:22:08.063)
WSREP_SST: [INFO] Evaluating socat -u TCP-LISTEN:4444,reuseaddr stdio | tar xfi - --recursive-unlink -h; RC=( ${PIPESTATUS[@]}
 ) (20131212 17:22:08.092)
131212 17:22:08 [Note] WSREP: Prepared SST request: xtrabackup|192.168.xxx.xxx:4444/xtrabackup_sst
131212 17:22:08 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
131212 17:22:08 [Note] WSREP: Assign initial position for certification: 1, protocol version: 2
131212 17:22:08 [Warning] WSREP: Failed to prepare for incremental state transfer: Local state UUID (00000000-0000-0000-0000-000000000000) does not match group state UUID (64863b36-62f7-11e3-bef2-a746941be182): 1 (Operation not permitted)
         at galera/src/replicator_str.cpp:prepare_for_IST():445. IST will be unavailable.
131212 17:22:08 [Note] WSREP: Node 1 (xxx) requested state transfer from '*any*'. Selected 0 (xxx)(SYNCED) as donor.
131212 17:22:08 [Note] WSREP: Shifting PRIMARY -> JOINER (TO: 1)
131212 17:22:08 [Note] WSREP: Requesting state transfer: success, donor: 0
tar: これは tar アーカイブではないようです
tar: 処理中にエラーが起きましたが、最後まで処理してからエラー終了させました
WSREP_SST: [ERROR] Error while getting data from donor node:  exit codes: 0 2 (20131212 17:22:09.063)
WSREP_SST: [ERROR] Cleanup after exit with status:32 (20131212 17:22:09.068)
131212 17:22:09 [Warning] WSREP: 0 (xxx): State transfer to 1 (xxx) failed: -1 (Operation not permitted)
131212 17:22:09 [ERROR] WSREP: gcs/src/gcs_group.c:gcs_group_handle_join_msg():719: Will never receive state. Need to abort.

SSTに失敗したログが出てて、DONOR側でも、

131214 16:12:12 [Note] WSREP: Shifting SYNCED -> DONOR/DESYNCED (TO: 4)
131214 16:12:12 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
131214 16:12:12 [Note] WSREP: Running: 'wsrep_sst_xtrabackup --role 'donor' --address '192.168.xxx.xxx:4444/xtrabackup_sst' --au
th '(null)' --socket '/xxx/mysql.sock' --datadir '/xxx/' --defaults-file '/xxx/my.cnf'
--gtid '64863b36-62f7-11e3-bef2-a746941be182:4''
131214 16:12:12 [Note] WSREP: sst_donor_thread signaled with 0
WSREP_SST: [INFO] Streaming with tar (20131214 16:12:13.133)
WSREP_SST: [INFO] Using socat as streamer (20131214 16:12:13.138)
WSREP_SST: [INFO] Streaming the backup to joiner at 192.168.xxx.xxx 4444 (20131214 16:12:13.154)
WSREP_SST: [INFO] Evaluating innobackupex --defaults-file=/xxx/my.cnf $INNOEXTRA --galera-info --stream=$sfmt ${T
MPDIR} 2>${DATA}/innobackup.backup.log | socat -u stdio TCP:192.168.xxx.xxx:4444; RC=( ${PIPESTATUS[@]} ) (20131214 16:12:13.159
)
WSREP_SST: [ERROR] innobackupex finished with error: 1.  Check /xxx//innobackup.backup.log (20131214 16:12:13.569
)
WSREP_SST: [ERROR] Cleanup after exit with status:22 (20131214 16:12:13.574)
131214 16:12:13 [ERROR] WSREP: Failed to read from: wsrep_sst_xtrabackup --role 'donor' --address '192.168.xxx.xxx:4444/xtraback
up_sst' --auth '(null)' --socket '/xxx/mysql.sock' --datadir '/xxx/' --defaults-file '/xxx/my.cnf' --gtid '64863b36-62f7-11e3-bef2-a746941be182:4'
131214 16:12:13 [ERROR] WSREP: Process completed with error: wsrep_sst_xtrabackup --role 'donor' --address '192.168.xxx.xxx:4444/xtrabackup_sst' --auth '(null)' --socket '/xxx/mysql.sock' --datadir '/xxx/' --defaults-file '/xxx/my.cnf' --gtid '64863b36-62f7-11e3-bef2-a746941be182:4': 22 (Invalid argument)
131214 16:12:13 [Warning] WSREP: 1 (xxx): State transfer to 0 (xxx) failed: -1 (Operation not permitted)

innobackupexが失敗したログが出る。

innobackupexのログを見てみると、

131214 16:47:12  innobackupex: Connecting to MySQL server with DSN 'dbi:mysql:;mysql_read_default_file=/xxx/my.cnf;mysql_read_default_group=xtrabackup' (using password: NO).
innobackupex: Error: Failed to connect to MySQL server: DBI connect(';mysql_read_default_file=/xxx/my.cnf;mysql_read_default_group=xtrabackup','',...) failed: Access denied for user 'mysql'@'localhost' (using password: NO) at /usr/local/bin/innobackupex line 2954

うーん、wsrep_sst_authでユーザー名とパスワードを指定してるのに、まるっと無視されている様子。取り敢えず、my.cnfの[xtrabackup]セクションに
[xtrabackup]
user= username
password= password
を追加して通るようにはなったけど、これバグなのか調べ方が悪いのかよく判らん。。


上手く行ってからメモ用にわざと失敗させてログを吐かせてるので、時間がバラバラなのはご愛嬌。


【2013/12/16 18:00】
Indeed, this is not a bug.

wsrep_sst_auth=username:password

でいけた。スペース入れるとダメぽい。

【2013/12/17 10:34】
違う、判った。
wsrep_sst_authはドナーノードに設定しないといけないオプションであり、しかも、mysqldセクションに書いている限り再起動しないと再読み込みされないので、ドナーノードを再起動してやるか、SET GLOBAL wsrep_sst_auth= ..で設定してやらないといけない。

_| ̄|○

2013年12月6日金曜日

あなたのMySQL 5.6トレンド力をチェックする15の質問

このエントリーは MySQL Casual Advent Calendar 2013 参加記事です。カジュアルカジュアル。
MySQL 5.6のGAリリースからはや10ヶ月、みなさんそろそろカジュアルに導入なされていることだと思います。

漢(オトコ)のコンピュータ道: 優れたMySQL DBAを見分ける27+3の質問 のオマージュです。
Islands in the byte stream: 「優れたPerlプログラマを見分ける27の質問」の日本語訳@__gfx__さん からメンションをいただいたので作りました :)

がんばってみます :)
独断と偏見で有名そうなの並べてあるだけですので、他にも色々ありますよ探してみましょう :)

  1. mysql_install_dbに加わった新機能2つ。
  2. mysqlコマンドラインクライアントは~/.mysql_historyにコマンド履歴を格納するが、5.6から--histignoreオプションで指定した文字列と'ある文字列'を含む行は格納されなくなった(上矢印とか押しても履歴として出てこない) この除外される文字列2つ。
    • ユーザーを量産する時にちょっと不便(´・ω・`)
    • こたえ=> "PASSWORDとIDENTIFIED"
    • なお、これ以外の文字列を--histignoreで指定しても上書きはされず、追加されるだけなので無効化するにはソースコードをいじる必要がある。
  3. InnoDBに追加された新機能を5つ以上
  4. 予めWHERE句以外でパーティションを指定してSELECT, UPDATE, DELETEその他が可能になったが、そのシンタックス。
  5. 5.6になって *非推奨* になった機能2つ以上
  6. 待望のスレーブ自動昇格スクリプト mysqlfailover を動作させるための条件
    • こたえ=> GTIDが有効になっていること
  7. クラッシュセーフスレーブに必要なパラメータ2つ
  8. mysqlbinlogをバイナリーログのリアルタイムバックアップとして使う時のオプション2つ
  9. レプリケーション関連で追加された新機能3つ
  10. 5.6になってオプティマイザーは賢くなったか? [Y/N]
  11. 不正Connectのカウントアップがついにテーブルで参照できるように! スキーマとテーブルは?
  12. 5.6未満から5.6への移行はmysqldump推奨。なんで?
  13. mysql_config_editorで作った.mylogin.cnfの最大の弱点は?
  14. 5.6で追加された新しいEXPLAIN2種類
  15. Optimizer Traceの出力させ方

    さて、みなさん如何でしたか?
    答えはほとんどナッツシェルからたどればいけます。ここにピックアップしなかったものも色々ありますので、「へーこんなの追加されてたんだー」とか思っていただければ幸いです。



    明日は bluerabbit777jpさん です!

    2013年12月3日火曜日

    全文検索エンジンGroongaを囲む夕べ(以下、ぐるんべ)4に参加して感じたことなど

    このエントリーは 全文検索エンジンGroonga Advent Calendar 2013 の3日目です :)

    さて、今年もいい肉の日(11/29)に ぐるんべ4 が開催されたので今年も行ってきました。去年のぐるんべ3に続き、2年連続2回目の参加です(去年は発表とかしませんでしたが)

    少し遅れ馳せながら感想エントリーです。
    当日のまとめは おんがえしさんブログのおんがえし Groongaを囲む夕べ4をサクッと振り返る などにリンクを張りつつ誤魔化します。


    さて、今年のぐるんべで受けた印象は *かなりMySQLに寄ってきたな* というイメージでした。かなり偏見ですが。

    すとーさん が`*roonga使ってる人ー?'と振った感じでも、去年よりMroonga使いは多そう。それに対してRroonga使いの参加が少なかったイメージです。

    去年のぐるんべ3 のアジェンダと比較していただくと判るのですが(すいません、具体的な数はタイトル見ても思い出せませんでした。。)去年は半分くらいがRroongaネタ、残りがGroongaとMroonga(2本?)で、どちらかというと比較的少数派だったはず。え? Nroo…ごめん誰か来たみたい

    ところが今年は 林さん のセッションを除けば事例紹介は半分(4本)がMroonga関連、Groongaが3本にRroongaが1本といううーん、これは我ながらバイアスのかかった見方だとは思うんですが、ボリューム的にだいぶ増えた気がするんですよ。気がするんです。

    その他にも池田さんから「Mroongaサポートの紹介」があって、対応する(?)南さんのセッションはプロダクトに関わらず*roonga族全般'に関するもの、斯波さん からのMroonga今年の収穫は去年と変わらないペースだったので、やっぱりMroongaの話題が出ていた時間は長かったように思われます。
    去年の 森さんのセッション では割と`全文検索もできる *KVS*'っぽく紹介されていた感じがしましたが、今年のセッションではそれに触れてはいたものの分量は少なくなった感じ(今年はGroonga本体でなくてDroongaでしたしね)

    別に良い訳でも悪い訳でもなく、なんとなーく、そんなことを感じました。来年はどうなるでしょうね。来年こそNroo…うん何でもない。


    そういえば去年のぐるんべで斯波さんに「ねえねえMariaDBマダー?」とねだった事とか色々思い出してきました。懐かしいですが、長くなりそうなのでこのへんで。

    ( ´-`).oO(ところで、httpしゃべれるようにするとかNode.jsから叩けるようにするのは最近の流行りなんですかね。NDBCLUSTERから学ぶところとしては、memcachedプロトコルなら使う人いるかもって感じですが


    明日は KitaitiMakotoさん です!