murata satoshi
murat****@gmail*****
2017年 1月 24日 (火) 22:45:38 JST
むらたです。毎度お世話になっております。
Mroongaストレージモードでmysqldがクラッシュすることがあるので報告します。
*再現手順が確立できていない状態での報告となってしまい申し訳ありません。
Amazon Linux AMI 2016.09.1 (4.4.19-29.55.amzn1.x86_64)
MySQL: 5.7.17、Groonga: 6.1.4、Mroonga: 6.13 (6.1.1/6.11でも発生)
---- A.
Thread pointer: 0x7f407c433e20
stack_bottom = 7f40901aeea8 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x35)[0xf42a95]
/usr/sbin/mysqld(handle_fatal_signal+0x4a4)[0x7cd8b4]
/lib64/libpthread.so.0(+0xf100)[0x7f43e05e3100]
/usr/lib64/libgroonga.so.0(+0x1bd6d5)[0x7f42395456d5]
/usr/lib64/libgroonga.so.0(grn_ii_cursor_next+0x13)[0x7f4239545843]
/usr/lib64/libgroonga.so.0(+0x1182f8)[0x7f42394a02f8]
/usr/lib64/libgroonga.so.0(grn_table_select+0x2ae)[0x7f42394a0f6e]
/usr/lib64/libgroonga.so.0(+0x33864a)[0x7f42396c064a]
/usr/lib64/libgroonga.so.0(+0x3390c6)[0x7f42396c10c6]
/usr/lib64/libgroonga.so.0(+0x33b7d1)[0x7f42396c37d1]
/usr/lib64/libgroonga.so.0(grn_proc_call+0xcd)[0x7f42394905bd]
/usr/lib64/libgroonga.so.0(grn_command_run+0x76)[0x7f4239434326]
/usr/lib64/libgroonga.so.0(grn_expr_exec+0x281)[0x7f42394a17c1]
/usr/lib64/libgroonga.so.0(grn_ctx_qe_exec+0x653)[0x7f42394393a3]
/usr/lib64/libgroonga.so.0(grn_ctx_send+0x545)[0x7f423943ab35]
/usr/lib64/mysql/plugin/ha_mroonga.so(mroonga_command+0x52)[0x7f424555f4e2]
/usr/sbin/mysqld(_ZN11udf_handler7val_strEP6StringS1_+0x6e)[0x88c27e]
/usr/sbin/mysqld(_ZN17Item_func_udf_str7val_strEP6String+0x1c)[0x88c33c]
/usr/sbin/mysqld(_ZN4Item4sendEP8ProtocolP6String+0x41)[0x824461]
/usr/sbin/mysqld(_ZN3THD19send_result_set_rowEP4ListI4ItemE+0xe9)[0xcc6d39]
/usr/sbin/mysqld(_ZN17Query_result_send9send_dataER4ListI4ItemE+0x6b)[0xcc6e4b]
/usr/sbin/mysqld(_ZN4JOIN4execEv+0x4a9)[0xcde1f9]
/usr/sbin/mysqld(_Z12handle_queryP3THDP3LEXP12Query_resultyy+0x250)[0xd48ab0]
/usr/sbin/mysqld[0xd095b3]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THDb+0x3958)[0xd0d1d8]
/usr/sbin/mysqld(_ZN18Prepared_statement7executeEP6Stringb+0x358)[0xd383e8]
/usr/sbin/mysqld(_ZN18Prepared_statement12execute_loopEP6StringbPhS2_+0xdb)[0xd3866b]
/usr/sbin/mysqld(_Z19mysqld_stmt_executeP3THDmmPhm+0x11d)[0xd38aed]
/usr/sbin/mysqld(_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command+0xb30)[0xd0f930]
/usr/sbin/mysqld(_Z10do_commandP3THD+0x194)[0xd10ea4]
/usr/sbin/mysqld(handle_connection+0x29c)[0xde3f1c]
/usr/sbin/mysqld(pfs_spawn_thread+0x174)[0xf60b74]
/lib64/libpthread.so.0(+0x7dc5)[0x7f43e05dbdc5]
/lib64/libc.so.6(clone+0x6d)[0x7f43df09ec9d]
---- B.
Thread pointer: 0x7f3634078280
stack_bottom = 7f36c99bdea8 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x35)[0xf42a95]
/usr/sbin/mysqld(handle_fatal_signal+0x4a4)[0x7cd8b4]
/lib64/libpthread.so.0(+0xf100)[0x7f3d5c6e3100]
/usr/lib64/libgroonga.so.0(+0x1bd6d5)[0x7f39169246d5]
/usr/lib64/libgroonga.so.0(grn_ii_cursor_next+0x13)[0x7f3916924843]
/usr/lib64/libgroonga.so.0(+0x1182f8)[0x7f391687f2f8]
/usr/lib64/libgroonga.so.0(grn_table_select+0x2ae)[0x7f391687ff6e]
/usr/lib64/mysql/plugin/ha_mroonga.so(_ZN10ha_mroonga26generic_ft_init_ext_selectEjjP6String+0x350)[0x7f391c303e70]
/usr/lib64/mysql/plugin/ha_mroonga.so(_ZN10ha_mroonga19generic_ft_init_extEjjP6String+0xa8)[0x7f391c304028]
/usr/lib64/mysql/plugin/ha_mroonga.so(_ZN10ha_mroonga19storage_ft_init_extEjjP6String+0x9)[0x7f391c304319]
/usr/sbin/mysqld(_ZN15Item_func_match11init_searchEP3THD+0x141)[0x890671]
/usr/sbin/mysqld(_Z12init_ftfuncsP3THDP13st_select_lex+0x4c)[0xcac05c]
/usr/sbin/mysqld(_ZN4JOIN8optimizeEv+0x2032)[0xd048c2]
/usr/sbin/mysqld(_ZN13st_select_lex8optimizeEP3THD+0x672)[0xd487d2]
/usr/sbin/mysqld(_Z12handle_queryP3THDP3LEXP12Query_resultyy+0x21f)[0xd48a7f]
/usr/sbin/mysqld[0xd095b3]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THDb+0x3958)[0xd0d1d8]
/usr/sbin/mysqld(_ZN18Prepared_statement7executeEP6Stringb+0x358)[0xd383e8]
/usr/sbin/mysqld(_ZN18Prepared_statement12execute_loopEP6StringbPhS2_+0xdb)[0xd3866b]
/usr/sbin/mysqld(_Z19mysqld_stmt_executeP3THDmmPhm+0x11d)[0xd38aed]
/usr/sbin/mysqld(_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command+0xb30)[0xd0f930]
/usr/sbin/mysqld(_Z10do_commandP3THD+0x194)[0xd10ea4]
/usr/sbin/mysqld(handle_connection+0x29c)[0xde3f1c]
/usr/sbin/mysqld(pfs_spawn_thread+0x174)[0xf60b74]
/lib64/libpthread.so.0(+0x7dc5)[0x7f3d5c6dbdc5]
/lib64/libc.so.6(clone+0x6d)[0x7f3d5b19ec9d]
----
A.のケースが多いです。
A.のケースでcore dump取得したのでそこから抜粋。
#0 0x00007f43e05e0741 in __pthread_kill (threadid=<optimized out>, signo=11) at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:61
#1 0x00000000007cd814 in handle_fatal_signal (sig=11)
at /export/home/pb2/build/sb_0-21378219-1480342906.75/rpm/BUILD/mysql-5.7.17/mysql-5.7.17/sql/signal_handler.cc:220
#2 <signal handler called>
#3 0x00007f42395456d5 in grn_ii_cursor_next_internal (ctx=0x7f402004f9c0, c=0x7f407c569130, options=<optimized out>) at ii.c:5102
#4 0x00007f4239545843 in grn_ii_cursor_next (ctx=<optimized out>, c=<optimized out>) at ii.c:5328
#5 0x00007f42394a02f8 in grn_table_select_index_equal (res=0x7f407c1962d0, si=0x7f407c5b8680, index=<optimized out>,
table=<optimized out>, ctx=0x7f402004f9c0) at expr.c:5999
#6 grn_table_select_index (ctx=0x7f402004f9c0, table=<optimized out>, si=0x7f407c5b8680, res=0x7f407c1962d0,
min_id=<optimized out>) at expr.c:6654
#7 0x00007f42394a0f6e in grn_table_select (ctx=0x7f402004f9c0, table=0x7f42116cc050, expr=<optimized out>, res=0x7f407c1962d0,
op=<optimized out>) at expr.c:6903
#8 0x00007f42396c064a in grn_filter_data_execute (ctx=0x7f402004f9c0, data=0x7f40901a9890, table=0x7f42116cc050,
tag=<optimized out>) at proc_select.c:817
#9 0x00007f42396c10c6 in grn_select_filter (data=0x7f40901a9880, ctx=0x7f402004f9c0) at proc_select.c:1407
#10 grn_select (ctx=0x7f402004f9c0, data=<optimized out>) at proc_select.c:3009
#11 0x00007f42396c37d1 in command_select (ctx=0x7f402004f9c0, nargs=<optimized out>, args=<optimized out>,
user_data=0x7f40901a9b00) at proc_select.c:3539
....
#3 0x00007f42395456d5 in grn_ii_cursor_next_internal (ctx=0x7f402004f9c0, c=0x7f407c569130, options=<optimized out>) at ii.c:5102
5102 c->pc.rest = c->pc.tf = 1 + *c->ctp++;
*c->ctp++ で死んでいるようです。
----
** セキュリティ的にあまり詳細まで開示できませんが出来る範囲で。。**
- 対象テーブルレコード件数: 約1,600,000
- Fulltext indexはマルチカラム(2カラム)でTokenBigramSplitSymbolAlphaDigit + NormalizerAuto
- 参照型ベクタカラムがあります。
- select、insert、update、delete全て実行しています。(発行数:select>update>insert>delete)
- mroonga_command経由のselectと通常のSQLでのselectが混在しています。
- 通常のSQLでのselectでは、match...against有/無が混在しています。
- 上記core dumpの該当Threadで実行されていたのはmroonga_command経由でのselectですが、全文検索ではありません。(drilldown付き)
* SELECT mroonga_command('select xxx_tbl --filter "xx_column1==1&&xx_column2==0" --limit 0 --drilldown xx_column3 \
--drilldown_filter _nsubrecs>=1 --drilldown_limit 32') AS result
* 同じSQLを同じ環境で発行しても再現しません。
- 上記core dumpでは他のThreadで更新処理は流れていませんでした(selectのみ、全文検索なし)。
----
- 発生頻度は0〜数回/日
- 昨年12月頃から発生?(6.1.1/6.11に上げてからか、その時期に行ったSQL修正等が原因かは不明)
- 複数のサーバで発生していますが、同時発生は今の所ありません。
- クラッシュ→再起動→即クラッシュ...のケースもあります。
- index再構築(alterでdisable/enable keys)しても再発します。
- GRN_II_CURSOR_SET_MIN_ENABLE=noを設定した場合でも発生しました。
- 発生時間に特に法則はないようです。
- 発生時のgeneral logを取得してテスト環境で流しても発生しませんでした。
- 上記のcore dumpから抽出したSQLをテスト環境で流しても発生しませんでした。
- groonga.log(level:NOTICE)には特に有意なログは残っていません。
下記が出ている時がありますが、クラッシュするタイミングとは関係なく出ています。
...|w|7581e700|[ii][cursor] chunk(35616) is reused by another thread: ...
- クラッシュした後 mroonga_operationsに type:update のレコードが残っているケースが多いです(100%ではありません)。
何か必要な情報、或いは情報取得のための手段がありましたらお申し付けください。
以上、よろしくお願いいたします。
むらた