Bug #1796

mroongaのレプリケーション構成で、stop slave;のタイミングでmroongaテーブルの更新を行っているとロック競合が発生するようです。

Added by Kentoku SHIBA about 5 years ago. Updated about 5 years ago.

Status:保留中Start date:06/30/2013
Priority:NormalDue date:
Assignee:Kouhei Sutou% Done:

20%

Category:-
Target version:-

Description

不具合概要

レプリケーションを止めた後にMySQLを止めようと、stop slave;を発行したら、その実行が終わらなくなりました。 該当のタイミングでちょうどmroongaテーブルの更新を行っており、それとバッティングしたと思われます。 約3時間後、タイムアウトとなりエラーログに記録されました。 stop slave; が行われたら、走っているクエリの実行が終わるまで待ち、その後にstop slave;の動作が行われるようにして欲しいです。

環境

CentOS 6.4と、以下の組み合わせです。

mysql> show variables like 'mroonga%';
+------------------------------------+-------------------+
| Variable_name                      | Value             |
+------------------------------------+-------------------+
| mroonga_database_path_prefix       |                   |
| mroonga_default_parser             | TokenBigram       |
| mroonga_default_wrapper_engine     |                   |
| mroonga_dry_write                  | OFF               |
| mroonga_enable_optimization        | ON                |
| mroonga_libgroonga_version         | 3.0.4-81-g19b8ebb |
| mroonga_log_file                   | groonga.log       |
| mroonga_log_level                  | NOTICE            |
| mroonga_match_escalation_threshold | 0                 |
| mroonga_version                    | 3.05              |
+------------------------------------+-------------------+
10 rows in set (0.00 sec)
$ rpm -qa | grep -e oon -e MySQL | sort
groonga-3.0.4.2013.06.18-0.el6.x86_64
groonga-devel-3.0.4.2013.06.18-0.el6.x86_64
groonga-libs-3.0.4.2013.06.18-0.el6.x86_64
groonga-normalizer-mysql-1.0.4.2013.06.18-1.el6.x86_64
groonga-plugin-suggest-3.0.4.2013.06.18-0.el6.x86_64
groonga-tokenizer-mecab-3.0.4.2013.06.18-0.el6.x86_64
MySQL-client-5.6.12-1.el6.x86_64
MySQL-devel-5.6.12-1.el6.x86_64
mysql-mroonga-3.04.2013.06.21-0.el6.mysql56.x86_64
MySQL-server-5.6.12-1.el6.x86_64
MySQL-shared-5.6.12-1.el6.x86_64
MySQL-shared-compat-5.6.12-1.el6.x86_64
perl-DBD-MySQL-4.013-3.el6.x86_64

ログ

mysqld.log

2013-06-27 19:08:33 2495 [ERROR] Slave SQL: Error 'grn_io_lock failed' on query. Default database:
'*****'. Query: 'INSERT INTO ****_search (`ID`,member_id...snip...) VALUES (NULL,234374,...snip...)', 
Error_code: 1026
2013-06-27 19:08:33 2495 [ERROR] Error writing relay log configuration.

groonga.log

2013-06-27 16:12:34.390538|n|51903720|mroonga 3.05 started.
2013-06-27 16:12:34.390561|n|51903720|log level is 'NOTICE'
2013-06-27 16:12:35.522543|n|50062700|io(*****.mrn.0000111) collisions(1000/122): lock failed 1000 times
2013-06-27 16:30:10.304035|n|50062700|io(*****.mrn.0000111) collisions(1000000/122)
2013-06-27 16:47:46.023961|n|50062700|io(*****.mrn.0000111) collisions(2000000/122)
2013-06-27 17:05:21.810373|n|50062700|io(*****.mrn.0000111) collisions(3000000/122)
2013-06-27 17:22:57.705092|n|50062700|io(*****.mrn.0000111) collisions(4000000/122)
2013-06-27 17:40:33.676196|n|50062700|io(*****.mrn.0000111) collisions(5000000/122)
2013-06-27 17:58:09.590802|n|50062700|io(*****.mrn.0000111) collisions(6000000/122)
2013-06-27 18:15:45.499125|n|50062700|io(*****.mrn.0000111) collisions(7000000/122)
2013-06-27 18:33:21.402383|n|50062700|io(*****.mrn.0000111) collisions(8000000/122)
2013-06-27 18:50:57.344633|n|50062700|io(*****.mrn.0000111) collisions(9000000/122)
2013-06-27 19:08:33.220564|n|50062700|io(*****.mrn.0000111) collisions(10000000/122)
2013-06-27 19:08:33.221666|w|50062700|[DB Locked] time out(10000000): io(*****.mrn.0000111) collisions(10000000/122)
2013-06-27 19:08:33.221692|e|50062700|grn_io_lock failed
2013-06-27 19:08:33.262107|e|50062700|/usr/lib64/libgroonga.so.0(grn_io_lock+0x20e) [0x3404f2f35e]
2013-06-27 19:08:33.262128|e|50062700|/usr/lib64/libgroonga.so.0(grn_ii_column_update+0xc8) [0x3404f2b828]
2013-06-27 19:08:33.262134|e|50062700|/usr/lib64/libgroonga.so.0(grn_column_index_update+0x3a) [0x3404e2f22a]
2013-06-27 19:08:33.262140|e|50062700|/usr/lib64/mysql/plugin/ha_mroonga.so(_ZN10ha_mroonga23wrapper_write_row_indexEPh+0x402) [0x7fc36ade0102]
2013-06-27 19:08:33.262146|e|50062700|/usr/sbin/mysqld(_ZN7handler12ha_write_rowEPh+0xa9) [0x5a6c09]
2013-06-27 19:08:33.262151|e|50062700|/usr/sbin/mysqld(_Z12write_recordP3THDP5TABLEP9COPY_INFOS4_+0x8a) [0x6bb29a]
2013-06-27 19:08:33.262157|e|50062700|/usr/sbin/mysqld(_Z12mysql_insertP3THDP10TABLE_LISTR4ListI4ItemERS3_IS5_ES6_S6_15enum_duplicatesb+0xb70) [0x6c2950]
2013-06-27 19:08:33.262163|e|50062700|/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x78e) [0x6d602e]
2013-06-27 19:08:33.262168|e|50062700|/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x32f) [0x6da5ff]
2013-06-27 19:08:33.262174|e|50062700|/usr/sbin/mysqld(_ZN15Query_log_event14do_apply_eventEPK14Relay_log_infoPKcj+0x5d7) [0x868977]
2013-06-27 19:08:33.262179|e|50062700|/usr/sbin/mysqld(_ZN9Log_event11apply_eventEP14Relay_log_info+0x74) [0x86cf44]
2013-06-27 19:08:33.262185|e|50062700|/usr/sbin/mysqld(_Z26apply_event_and_update_posPP9Log_eventP3THDP14Relay_log_info+0x25e) [0x896b0e]
2013-06-27 19:08:33.262190|e|50062700|/usr/sbin/mysqld() [0x89c921]
2013-06-27 19:08:33.262196|e|50062700|/usr/sbin/mysqld(handle_slave_sql+0xbda) [0x89fada]
2013-06-27 19:08:33.262201|e|50062700|/usr/sbin/mysqld(pfs_spawn_thread+0x139) [0x949f69]
2013-06-27 19:08:33.262207|e|50062700|/lib64/libpthread.so.0() [0x3240a07851]

SHOW PROCESSLIST;

mysql> show full processlist;
+-----+-------------+-----------+--------+---------+------+----------------------------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Id  | User        | Host      | db     | Command | Time | State                            | Info                                                                                                                                                                                                                                                                      |
+-----+-------------+-----------+--------+---------+------+----------------------------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
|   1 | system user |           | NULL   | Connect |  946 | Waiting for master to send event | NULL                                                                                                                                                                                                                                                                      |
|   2 | system user |           | ***** | Connect |  953 | update                           | INSERT INTO ****_search (`ID`,member_id...snip...) VALUES (NULL,234374,...snip...)                 |
|  61 | root        | localhost | NULL   | Killed  |  725 | Killing slave                    | stop slave                                                                                                                                                                                                                                                                |
|  70 | root        | localhost | NULL   | Killed  |  643 | init                             | show slave status                                                                                                                                                                                                                                                         |
| 102 | root        | localhost | NULL   | Query   |    0 | init                             | show full processlist                                                                                                                                                                                                                                                     |
| 131 | root        | localhost | mysql  | Query   |  491 | executing                        | SHOW GLOBAL STATUS                                                                                                                                                                                                                                                        |
| 160 | root        | localhost | NULL   | Sleep   |  393 |                                  | NULL                                                                                                                                                                                                                                                                      |
| 213 | root        | localhost | mysql  | Query   |  191 | executing                        | SHOW GLOBAL STATUS                                                                                                                                                                                                                                                        |
+-----+-------------+-----------+--------+---------+------+----------------------------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
8 rows in set (0.00 sec)

スキーマ

CREATE TABLE `***_search` (
  `id` int(10) unsigned NOT NULL AUTO_INCREMENT,
  `member_id` int(10) unsigned NOT NULL,
  `data` text NOT NULL,
  `updated_at` datetime NOT NULL,
  `created_at` datetime NOT NULL,
  PRIMARY KEY (`id`),
  KEY `member_id` (`member_id`),
  FULLTEXT KEY `data` (`data`) COMMENT 'parser "TokenMecab"'
) ENGINE=mroonga AUTO_INCREMENT=234353 DEFAULT CHARSET=utf8 COMMENT='engine "innodb"';

History

#1 Updated by Kentoku SHIBA about 5 years ago

  • Status changed from 新規 to 担当者作業中
  • % Done changed from 0 to 10

groongaのロックタイムアウトになっているようなので、 groongaのロックについて確認が必要。

#2 Updated by Kentoku SHIBA about 5 years ago

マスタでINSERTの負荷をかけた状態でスレーブでレプリケーションの停止・開始を
繰り返してみたが、現在のところ再現は確認できず。

#3 Updated by Kentoku SHIBA about 5 years ago

スレーブのMySQLをクラッシュさせて、テーブルにgroongaのロックが残ると、
再起動後にこの問題が確認できる。

#4 Updated by Kentoku SHIBA about 5 years ago

  • % Done changed from 10 to 20

レプリケーションでinsertが常時スレーブ上で実行されている状態にしておき
その同一のテーブルに対して時間がかかるload dataを実行している間に、
stop slaveを実施してみた。
結果は、stop slaveの完了は必ずload dataの完了まで待たされ、
ロックが残るという現象も確認できなかった。

話が前後するが、この作業の過程で、前回クラッシュさせて残ったロックを解放するために、

mysql> select mroonga_command('clearlock');
の実行を試みたところ、サーバがダウンした。
調査したところこれは、レプリケーションの実行が停止しておらず、レプリケーションによる
insertがgroongaのロックによって待たされている状態で、「clearlock」した際に発生していた。
レプリケーションを停止し、「clearlock」を実行すると本現象は発生しない。
サーバがダウンした際のスタックトレースは以下で、異常はThread 26で検知された。
Thread 27 (Thread 0x7fffb4259700 (LWP 915)):
#0  0x00007fffe3c48535 in grn_realloc_default (ctx=0x7fffa000a960, ptr=0x7fffa0140af0, size=0,
    file=0x7fffe3df6f94 "db.c", line=7343, func=0x7fffe3df68c2 "grn_obj_close") at ctx.c:2614
#1  0x00007fffe3c57ff0 in grn_obj_close (ctx=0x7fffa000a960, obj=0x7fffa0140a20) at db.c:7343
#2  0x00007fffe3c57be1 in grn_db_close (ctx=0x7fffa000a960, db=0x7fffa000aae0) at db.c:332
#3  0x00007fffe3c57f3c in grn_obj_close (ctx=0x7fffa000a960, obj=0x7fffa000aae0) at db.c:7308
#4  0x00007fffe406a60a in mroonga_command_deinit (initid=) at ha_mroonga.cpp:1130
#5  0x00000000005f03b0 in cleanup (this=0x7fffa00018b0) at /ssd1/mysql-5.6.11/sql/item_func.cc:3479
#6  Item_udf_func::cleanup (this=0x7fffa00018b0) at /ssd1/mysql-5.6.11/sql/item_func.cc:3786
#7  0x0000000000694a1a in delete_self (this=0x26c8120) at /ssd1/mysql-5.6.11/sql/item.h:1568
#8  free_items (this=0x26c8120) at /ssd1/mysql-5.6.11/sql/sql_class.cc:3293
#9  THD::cleanup_after_query (this=0x26c8120) at /ssd1/mysql-5.6.11/sql/sql_class.cc:2001
#10 0x00000000006d3b52 in dispatch_command (command=COM_QUERY, thd=0x26c8120, packet=0x278d0f1 "",
    packet_length=2684360419) at /ssd1/mysql-5.6.11/sql/sql_parse.cc:1336
#11 0x000000000069cf9d in do_handle_one_connection (thd_arg=)
    at /ssd1/mysql-5.6.11/sql/sql_connect.cc:977
#12 0x000000000069d0d2 in handle_one_connection (arg=) at /ssd1/mysql-5.6.11/sql/sql_connect.cc:893
#13 0x0000000000919686 in pfs_spawn_thread (arg=0x273fad0) at /ssd1/mysql-5.6.11/storage/perfschema/pfs.cc:1853
#14 0x00007ffff7bc7851 in start_thread (arg=0x7fffb4259700) at pthread_create.c:301
#15 0x00007ffff6b3211d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:115

Thread 26 (Thread 0x7fffb4218700 (LWP 913)): #0 __strncpy_sse2 (s1=0x7fffac887c8f "", s2=0x7fffb5207cbe < Address 0x7fffb5207cbe out of bounds >, n=8192) at ./strncpy.c:42 #1 0x00007fffb4ea4dc0 in MeCab::Param::open (this=0x7fffb42155d0, arg=, opts=0x7fffb52020e0) at param.cpp:194 #2 0x00007fffb4e8082f in MeCab::(anonymous namespace)::ModelImpl::open (this=0x7fffac3104c0, arg=0x7fffb5207cbe < Address 0x7fffb5207cbe out of bounds >) at tagger.cpp:360 #3 0x00007fffb4e80ae7 in open (argv=0x7fffb5207cbe < Address 0x7fffb5207cbe out of bounds >) at tagger.cpp:469 #4 MeCab::createTagger (argv=0x7fffb5207cbe < Address 0x7fffb5207cbe out of bounds >) at tagger.cpp:1061 #5 0x00007fffb4ecf409 in mecab_new2 (arg=) at libmecab.cpp:111 #6 0x00007fffb5207897 in ?? () #7 0x0000000000000100 in ?? () #8 0x00007fffe3c48a48 in grn_malloc_default (ctx=0x7fffac011a50, size=140736215472304, file=0x1 < Address 0x1 out of bounds >, line=-1400342848, func=) at ctx.c:2557 #9 0x00007fffe3de442a in grn_token_open (ctx=0x7fffb42158b0, table=0x7fffac30f590, str=, str_len=, mode=GRN_TOKEN_GET, flags=0) at token.c:525 #10 0x00007fffe3d3ae2a in grn_vector2updspecs (ctx=0x7fffac011a50, ii=, rid=43510, section=1, in=, out=0x7fffac887350, mode=GRN_TOKEN_ADD, posting=0x0) at ii.c:4979 #11 0x00007fffe3d4de75 in grn_ii_column_update (ctx=0x7fffac011a50, ii=0x7fffac30f7e0, rid=43510, section=1, oldvalue=0x0, newvalue=0x7fffac011c10, posting=0x0) at ii.c:5080 #12 0x00007fffe3c54fea in grn_column_index_update (ctx=0x7fffac011a50, column=, id=, section=, oldvalue=, newvalue=) at db.c:5788 #13 0x00007fffe407465a in ha_mroonga::wrapper_write_row_index (this=0x7fffac0108f0, buf=) at ha_mroonga.cpp:5508 #14 0x000000000058e580 in handler::ha_write_row (this=0x7fffac0108f0, buf=0x7fffac037780 ) at /ssd1/mysql-5.6.11/sql/handler.cc:7185 #15 0x00000000006b0df9 in write_record (thd=0x7fffac000990, table=0x7fffac00c250, info=0x7fffb42163c0, update=0x7fffb4216340) at /ssd1/mysql-5.6.11/sql/sql_insert.cc:1849 #16 0x00000000006b810f in mysql_insert (thd=0x7fffac000990, table_list=0x7fffac0051f0, fields=..., values_list=..., update_fields=..., update_values=, duplic=DUP_ERROR, ignore=false) at /ssd1/mysql-5.6.11/sql/sql_insert.cc:1027 #17 0x00000000006ce6a4 in mysql_execute_command (thd=0x7fffac000990) at /ssd1/mysql-5.6.11/sql/sql_parse.cc:3383 #18 0x00000000006d2927 in mysql_parse (thd=0x7fffac000990, rawbuf=, length=, parser_state=) at /ssd1/mysql-5.6.11/sql/sql_parse.cc:6161 #19 0x000000000087029c in Query_log_event::do_apply_event (this=0x7fffac00b480, rli=0x267c660, query_arg=0x7fffac00a7a0 "INSERT INTO xxx_search (\n member_id,\n data,\n updated_at,\n created_at\n ) VALUES (\n NAME_CONST('p_member_id',43509),\n CONCAT( NAME_CONST('p_member_id',43509),"..., q_len_arg=368) at /ssd1/mysql-5.6.11/sql/log_event.cc:4735 #20 0x0000000000879f68 in Log_event::apply_event (this=0x7fffac00b480, rli=0x267c660) at /ssd1/mysql-5.6.11/sql/log_event.cc:2970 #21 0x00000000008a50cc in apply_event_and_update_pos (ptr_ev=0x7fffb42176c0, thd=0x7fffac000990, rli=0x267c660) at /ssd1/mysql-5.6.11/sql/rpl_slave.cc:3349 #22 0x00000000008a5881 in exec_relay_log_event (thd=0x7fffac000990, rli=0x267c660) at /ssd1/mysql-5.6.11/sql/rpl_slave.cc:3717 #23 0x00000000008a6eaf in handle_slave_sql (arg=) at /ssd1/mysql-5.6.11/sql/rpl_slave.cc:5537 #24 0x0000000000919686 in pfs_spawn_thread (arg=0x2675c30) at /ssd1/mysql-5.6.11/storage/perfschema/pfs.cc:1853 #25 0x00007ffff7bc7851 in start_thread (arg=0x7fffb4218700) at pthread_create.c:301 #26 0x00007ffff6b3211d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:115

#5 Updated by Kentoku SHIBA about 5 years ago

  • Assignee changed from Kentoku SHIBA to Kouhei Sutou

お手数ではございますが、一度こちらの現象のご確認をお願いします。

#6 Updated by Kouhei Sutou about 5 years ago

  • Status changed from 担当者作業中 to 保留中

mroonga_command()でクラッシュするやつは https://github.com/groonga/groonga/commit/3b91ce16d97e94d074e806deff78404f470fa4ba と同じ問題な気がするので、これで直った気がします。

stop slave;でクラッシュするやつは再現しないという事なので、この問題は一旦諦めましょう。。。

#7 Updated by Kouhei Sutou about 5 years ago

今回のケースでは、groongaは0.001秒sleepしながら10000000回ロックを試みているので、(0.001 * 10000000) / 60 / 60 => 2.7777777777777777時間くらいロックを取ろうとがんばります。

実際、16:12:35にロックを取ろうと頑張り始めて、19:08:33に諦めているので、3時間弱がんばっています。これは↑の2.7時間とだいたい同じです。

もし、実行中の更新処理が2.7時間以上更新がかかるやつなら現象が再現すると思いますが、実際はそんなことないと思うので、原因はわからないですね。。。

Also available in: Atom PDF