OHTSUKA Soushi ( 大塚 総司 )
so****@ayd*****
2013年 2月 16日 (土) 14:32:31 JST
はじめまして。
mroongaを利用させていただいております。
曖昧な情報で申し訳ないのですが、mroongaのテーブル名を変更するとテーブルが
壊れるような事象が発生する可能性はありますでしょうか。
先日、MySQLがクラッシュする障害が発生しました。
そのクラッシュの直前にmroongaのテーブル名を変更しており、何かしら関係がある
のではないかと思っています。
経緯としては次のような感じです。
[環境情報]
MySQL 5.5.28
mroonga 2.10
groonga 2.1.1
[mrongaなテーブル情報]
※すべてストレージモードで利用しています
[DB1]
・テーブル数 :3
・レコード数(合計):約8万
[DB2]
・テーブル数 :3
・レコード数(合計):約9万
[備考]
それ以外にもinnodbテーブルが存在します
[21時頃]
・mroongaのテーブル名変更
(ALTER TABLEのRENAME)
[groonga.log]
------------------------------------------------------------(ここから)
2013-02-15 21:02:33.673759|e|41aef940|invalid table assigned
2013-02-15 21:02:33.682112|e|41aef940|/usr/local/groonga/lib/libgroonga.so.0(grn_table_size+0x26f) [0x2aaad2f6234f]
2013-02-15 21:02:33.682121|e|41aef940|/usr/local/mysql-5.5.28/lib/plugin/ha_mroonga.so(_ZN10ha_mroonga29storage_info_variable_recordsEv+0x17) [0x2aaad2ced407]
2013-02-15 21:02:33.682124|e|41aef940|/usr/local/mysql-5.5.28/lib/plugin/ha_mroonga.so(_ZN10ha_mroonga21storage_info_variableEv+0x9) [0x2aaad2cf7c29]
2013-02-15 21:02:33.682128|e|41aef940|/usr/local/mysql-5.5.28/lib/plugin/ha_mroonga.so(_ZN10ha_mroonga12storage_infoEj+0x148) [0x2aaad2cf7d88]
2013-02-15 21:02:33.682131|e|41aef940|/usr/local/mysql-5.5.28/bin/mysqld [0x59cce7]
2013-02-15 21:02:33.682134|e|41aef940|/usr/local/mysql-5.5.28/bin/mysqld [0x59d98c]
2013-02-15 21:02:33.682137|e|41aef940|/usr/local/mysql-5.5.28/bin/mysqld(_Z14get_all_tablesP3THDP10TABLE_LISTP4Item+0x51b) [0x5a845b]
2013-02-15 21:02:33.682140|e|41aef940|/usr/local/mysql-5.5.28/bin/mysqld(_Z24get_schema_tables_resultP4JOIN23enum_schema_table_state+0x1ed) [0x598b0d]
2013-02-15 21:02:33.682143|e|41aef940|/usr/local/mysql-5.5.28/bin/mysqld(_ZN4JOIN4execEv+0x43a) [0x5941aa]
2013-02-15 21:02:33.682149|e|41aef940|/usr/local/mysql-5.5.28/bin/mysqld(_Z12mysql_selectP3THDPPP4ItemP10TABLE_LISTjR4ListIS1_ES2_jP8st_orderSB_S2_SB_yP13select
_resultP18st_select_lex_unitP13st_select_lex+0x1c0) [0x596270]
2013-02-15 21:02:33.682152|e|41aef940|/usr/local/mysql-5.5.28/bin/mysqld(_Z13handle_selectP3THDP3LEXP13select_resultm+0x16f) [0x596b5f]
2013-02-15 21:02:33.682155|e|41aef940|/usr/local/mysql-5.5.28/bin/mysqld [0x55afa0]
2013-02-15 21:02:33.682158|e|41aef940|/usr/local/mysql-5.5.28/bin/mysqld(_Z21mysql_execute_commandP3THD+0x3b8c) [0x55f08c]
2013-02-15 21:02:33.682161|e|41aef940|/usr/local/mysql-5.5.28/bin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0xfe) [0x5613ce]
2013-02-15 21:02:33.682164|e|41aef940|/usr/local/mysql-5.5.28/bin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x1351) [0x5627a1]
2013-02-15 21:02:33.682167|e|41aef940|/usr/local/mysql-5.5.28/bin/mysqld(_Z10do_commandP3THD+0xc2) [0x562ac2]
2013-02-15 21:02:35.840815|n|068dd540|mroonga 2.10 started.
2013-02-15 21:02:35.840841|n|068dd540|log level is 'NOTICE'
2013-02-15 21:02:35.915122|e|068dd540|[tokenizer][mecab] MeCab has no dictionary that uses the context encoding: <utf8>
2013-02-15 21:02:35.917441|e|068dd540|/usr/local/groonga/lib/libgroonga.so.0(grn_plugin_logtrace+0x57) [0x2aaad3082537]
2013-02-15 21:02:35.917459|e|068dd540|/usr/local/groonga/lib/groonga/plugins/tokenizers/mecab.so(grn_plugin_impl_init+0xd9) [0x2aab186b89d9]
2013-02-15 21:02:35.917469|e|068dd540|/usr/local/groonga/lib/libgroonga.so.0(grn_plugin_open+0xd60) [0x2aaad3083dd0]
2013-02-15 21:02:35.917478|e|068dd540|/usr/local/groonga/lib/libgroonga.so.0(grn_plugin_register_by_path+0x69c) [0x2aaad3084edc]
2013-02-15 21:02:35.917487|e|068dd540|/usr/local/groonga/lib/libgroonga.so.0(grn_plugin_register+0x259) [0x2aaad3085519]
2013-02-15 21:02:35.917495|e|068dd540|/usr/local/groonga/lib/libgroonga.so.0(grn_db_init_builtin_types+0x387) [0x2aaad2f6b467]
2013-02-15 21:02:35.917527|e|068dd540|/usr/local/groonga/lib/libgroonga.so.0(grn_db_create+0x211) [0x2aaad2f6b771]
2013-02-15 21:02:35.917536|e|068dd540|/usr/local/mysql-5.5.28/lib/plugin/ha_mroonga.so [0x2aaad2ceb7c5]
2013-02-15 21:02:35.917545|e|068dd540|/usr/local/mysql-5.5.28/bin/mysqld(_Z24ha_initialize_handlertonP13st_plugin_int+0x41) [0x6579e1]
2013-02-15 21:02:35.917553|e|068dd540|/usr/local/mysql-5.5.28/bin/mysqld [0x56787b]
2013-02-15 21:02:35.917561|e|068dd540|/usr/local/mysql-5.5.28/bin/mysqld(_Z11plugin_initPiPPci+0xa42) [0x568442]
2013-02-15 21:02:35.917570|e|068dd540|/usr/local/mysql-5.5.28/bin/mysqld [0x4f2802]
2013-02-15 21:02:35.917578|e|068dd540|/usr/local/mysql-5.5.28/bin/mysqld(_Z11mysqld_mainiPPc+0x865) [0x4f5515]
2013-02-15 21:02:35.917586|e|068dd540|/lib64/libc.so.6(__libc_start_main+0xf4) [0x358701d994]
2013-02-15 21:02:35.917595|e|068dd540|/usr/local/mysql-5.5.28/bin/mysqld [0x4edd89]
------------------------------------------------------------(ここまで)
[MySQLのログ]
------------------------------------------------------------(ここから)
12:02:33 UTC - mysqld got signal 11 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed,
something is definitely wrong and this may fail.
key_buffer_size=536870912
read_buffer_size=4194304
max_used_connections=24
max_threads=320
thread_count=3
connection_count=3
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 3149375 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
Thread pointer: 0x8fc72b0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 41aef0f0 thread_stack 0x40000
/usr/local/mysql-5.5.28/bin/mysqld(my_print_stacktrace+0x2e)[0x76abfe]
/usr/local/mysql-5.5.28/bin/mysqld(handle_fatal_signal+0x386)[0x6558a6]
/lib64/libpthread.so.0[0x3587c0eb70]
/usr/local/groonga/lib/libgroonga.so.0(grn_obj_path+0x1)[0x2aaad2f58051]
/usr/local/mysql-5.5.28/lib/plugin/ha_mroonga.so(_ZN10ha_mroonga38storage_info_variable_data_file_lengthEv+0x2a)[0x2aaad2cf7aea]
/usr/local/mysql-5.5.28/lib/plugin/ha_mroonga.so(_ZN10ha_mroonga12storage_infoEj+0x148)[0x2aaad2cf7d88]
/usr/local/mysql-5.5.28/bin/mysqld[0x59cce7]
/usr/local/mysql-5.5.28/bin/mysqld[0x59d98c]
/usr/local/mysql-5.5.28/bin/mysqld(_Z14get_all_tablesP3THDP10TABLE_LISTP4Item+0x51b)[0x5a845b]
/usr/local/mysql-5.5.28/bin/mysqld(_Z24get_schema_tables_resultP4JOIN23enum_schema_table_state+0x1ed)[0x598b0d]
/usr/local/mysql-5.5.28/bin/mysqld(_ZN4JOIN4execEv+0x43a)[0x5941aa]
/usr/local/mysql-5.5.28/bin/mysqld(_Z12mysql_selectP3THDPPP4ItemP10TABLE_LISTjR4ListIS1_ES2_jP8st_orderSB_S2_SB_yP13select_resultP18st_select_lex_unitP13st_sele
ct_lex+0x1c0)[0x596270]
/usr/local/mysql-5.5.28/bin/mysqld(_Z13handle_selectP3THDP3LEXP13select_resultm+0x16f)[0x596b5f]
/usr/local/mysql-5.5.28/bin/mysqld[0x55afa0]
/usr/local/mysql-5.5.28/bin/mysqld(_Z21mysql_execute_commandP3THD+0x3b8c)[0x55f08c]
/usr/local/mysql-5.5.28/bin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0xfe)[0x5613ce]
/usr/local/mysql-5.5.28/bin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x1351)[0x5627a1]
/usr/local/mysql-5.5.28/bin/mysqld(_Z10do_commandP3THD+0xc2)[0x562ac2]
/usr/local/mysql-5.5.28/bin/mysqld(_Z24do_handle_one_connectionP3THD+0xf2)[0x5f0212]
/usr/local/mysql-5.5.28/bin/mysqld(handle_one_connection+0x4a)[0x5f02ea]
/lib64/libpthread.so.0[0x3587c0673d]
/lib64/libc.so.6(clone+0x6d)[0x35870d44bd]
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (2aab999c0600): is an invalid pointer
Connection ID (thread ID): 5911441
Status: NOT_KILLED
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
130215 21:02:33 mysqld_safe Number of processes running now: 0
130215 21:02:33 mysqld_safe mysqld restarted
130215 21:02:33 InnoDB: The InnoDB memory heap is disabled
130215 21:02:33 InnoDB: Mutexes and rw_locks use GCC atomic builtins
130215 21:02:33 InnoDB: Compressed tables use zlib 1.2.3
130215 21:02:34 InnoDB: Initializing buffer pool, size = 1.0G
130215 21:02:34 InnoDB: Completed initialization of buffer pool
130215 21:02:34 InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 36928405015
130215 21:02:34 InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
InnoDB: Doing recovery: scanned up to log sequence number 36928412193
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 1 row operations to undo
InnoDB: Trx id counter is 1EE2C400
130215 21:02:34 InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
InnoDB: Last MySQL binlog file position 0 252871667, file name ./mysql-bin.000131
InnoDB: Starting in background the rollback of uncommitted transactions
130215 21:02:34 InnoDB: Rolling back trx with id 1ED22229, 1 rows to undo
130215 21:02:34 InnoDB: Waiting for the background threads to start
InnoDB: Rolling back of trx id 1ED22229 completed
130215 21:02:34 InnoDB: Rollback of non-prepared transactions completed
130215 21:02:35 InnoDB: 1.1.8 started; log sequence number 36928412193
130215 21:02:35 [Note] Recovering after a crash using mysql-bin
130215 21:02:36 [Note] Starting crash recovery...
130215 21:02:36 [Note] Crash recovery finished.
130215 21:02:36 [Note] Server hostname (bind-address): '0.0.0.0'; port: 3306
130215 21:02:36 [Note] - '0.0.0.0' resolves to '0.0.0.0';
130215 21:02:36 [Note] Server socket created on IP: '0.0.0.0'.
130215 21:02:36 [Note] Event Scheduler: Loaded 0 events
130215 21:02:36 [Note] /usr/local/mysql-5.5.28/bin/mysqld: ready for connections.
------------------------------------------------------------(ここまで)
groonga.logに「invalid table assigned」が発生後、MySQLが再起動しているような
感じがしています。
その後、短時間に何度かMySQLが再起動され、その時に最新のバイナリログが何故か
なくなり、MySQLが起動しなくなりました。
mysql-bin.indexを修正しMySQLを再起動させたところ無事に起動したのですが、
mroongaのテーブルに対してクエリを行うと「invalid table assigned」が発生し、
MySQLが自動再起動する現象が発生しました。
innodbへのクエリは問題なく行えました。
結局一旦データベースをDROPし、バックアップからリストアすることで復旧させる
事が出来ました。
なお、テスト環境でもmroongaのテーブル名を変更していたのですが、こちらでは特に
問題は発生しておらず、今のところ問題の再現性はありません。
もしどなたか同様の現象があったり、心当たりがありましたら返信いただけると助か
ります。
取り合えずmroongaのテーブル名変更は怖いので今後は控えようかと思っています。
また、別件で質問した方がいいのかもしれませんが、データベースでmroonga関連の
テーブルをすべて削除したあと *.mrn や *.mrn.xxx ファイルが残っていたらこれは
手動で削除していいものでしょうか。
実は復旧作業中に別ユーザがmroongaテーブルにリクエスト→MySQLが再起動し、中途
半端にファイルが存在する事態になったため、念のためDB全削除、関連ファイルも全
削除からリストアを行いました。
///////////////////////////////////////////////////////////////
[NAME] 大塚 総司 - OTSUKA Soushi
[Mail] so****@ayd*****