Details
-
Bug
-
Status: Closed (View Workflow)
-
Critical
-
Resolution: Fixed
-
None
-
None
Description
perl ./mtr main.1st
|
#3 <signal handler called>
|
#4 0x00000000005fd08c in thd_get_ha_data (thd=0x7f1d6fb4b060, hton=0x7f1d70be9260) at /home/elenst/bzr/maria-5.5-galera/sql/sql_class.cc:626
|
#5 0x00000000008cfd42 in THD::binlog_get_pending_rows_event (this=0x7f1d6fb4b060, is_transactional=false) at /home/elenst/bzr/maria-5.5-galera/sql/log.cc:5073
|
#6 0x0000000000609ea6 in THD::binlog_flush_pending_rows_event (this=0x7f1d6fb4b060, stmt_end=true, is_transactional=false) at /home/elenst/bzr/maria-5.5-galera/sql/sql_class.cc:5560
|
#7 0x00000000005ec3f2 in THD::binlog_flush_pending_rows_event (this=0x7f1d6fb4b060, stmt_end=true) at /home/elenst/bzr/maria-5.5-galera/sql/sql_class.h:1793
|
#8 0x00000000005d906e in close_thread_tables (thd=0x7f1d6fb4b060) at /home/elenst/bzr/maria-5.5-galera/sql/sql_base.cc:1578
|
#9 0x00000000005e9e49 in close_mysql_tables (thd=0x7f1d6fb4b060) at /home/elenst/bzr/maria-5.5-galera/sql/sql_base.cc:9814
|
#10 0x00000000005bab61 in acl_reload (thd=0x7f1d6fb4b060) at /home/elenst/bzr/maria-5.5-galera/sql/sql_acl.cc:1251
|
#11 0x00000000005b8e0e in acl_init (dont_read_acl_tables=false) at /home/elenst/bzr/maria-5.5-galera/sql/sql_acl.cc:703
|
#12 0x0000000000591134 in mysqld_main (argc=81, argv=0x7f1d708140b0) at /home/elenst/bzr/maria-5.5-galera/sql/mysqld.cc:5692
|
#13 0x000000000058718c in main (argc=7, argv=0x7fffe3944d78) at /home/elenst/bzr/maria-5.5-galera/sql/main.cc:25
|
revision-id: jplindst@mariadb.org-20131204114628-jyd8vwg15kb1xtv2
|
date: 2013-12-04 13:46:28 +0200
|
build-date: 2013-12-04 18:44:34 +0400
|
revno: 3444
|
built as
cmake . -DCMAKE_BUILD_TYPE=Debug && make -j3
|
See for example
http://buildbot.askmonty.org/buildbot/builders/kvm-fulltest/builds/1887/steps/test_2/logs/stdio
Attachments
Activity
Problem is from fact that binlog_hton is not fully initialized because wsrep_provider is "none" and opt_bin_log is false. In this case there is additional check needed on sql_base.cc before thd->binlog_flush_pending_rows_event(TRUE) call because that will assume that binlog_hton is correctly initialized.
Added new guard on galera case not to call binlog function if wsrep provider is not provided and binlog is not enabled.
Hi Jan,
I did some post-analysis on the bug. The reason that you have specified is
correct,
but however, I feel the fix happen at a different place. (see inline)
On Thu, Dec 5, 2013 at 3:09 AM, Jan Lindström (JIRA) <
^^ the caller of this function (THD::binlog_flush_pending_rows_event)
already
makes sure that it should not proceed if binrary loggins is disabled or
wsrep
binlog emulation is not on.
.. snip ..
int THD::binlog_flush_pending_rows_event(bool stmt_end, bool
is_transactional)
{
DBUG_ENTER("THD::binlog_flush_pending_rows_event");
/*
We shall flush the pending event even if we are not in row-based
mode: it might be the case that we left row-based mode before
flushing anything (e.g., if we have explicitly locked tables).
*/
#ifdef WITH_WSREP
if (!(WSREP_EMULATE_BINLOG(this) || mysql_bin_log.is_open()))
#else
if (!mysql_bin_log.is_open())
#endif
DBUG_RETURN(0);
.. snip..
So, binlog flush should ideally not happen in our case. But the problem
showed up as wsrep_emulate_bin_log is later turned ON without checking
the wsrep provider status.
Please take a looks at the patch :
<patch>
=== modified file 'sql/mysqld.cc'
— sql/mysqld.cc 2013-11-29 18:03:00 +0000
+++ sql/mysqld.cc 2013-12-05 15:04:31 +0000
@@ -4679,7 +4679,11 @@
#endif
#ifdef WITH_WSREP
- if (!opt_bin_log)
+ /*
+ In case binlog is disabled & wsrep (wsrep_on) is ON, we switch
+ wsrep_emulate_bin_log ON only when a wsrep provider is specified.
+ */
+ if (!opt_bin_log && (WSREP_ON && WSREP_PROVIDER_EXISTS)) { wsrep_emulate_bin_log= 1; }
=== modified file 'sql/sql_base.cc'
— sql/sql_base.cc 2013-12-05 12:53:22 +0000
+++ sql/sql_base.cc 2013-12-05 15:17:24 +0000
@@ -62,7 +62,6 @@
#ifdef WITH_WSREP
#include "wsrep_mysqld.h"
-extern handlerton *binlog_hton;
#endif // WITH_WSREP
bool
@@ -1575,11 +1574,6 @@
handled either before writing a query log event (inside
binlog_query()) or when preparing a pending event.
*/
-#ifdef WITH_WSREP
- /* In Galera binlog is not enabled by default in case when
- wsrep provider is not specified. */
- if ((WSREP_ON && WSREP_PROVIDER_EXISTS) || binlog_hton->state ==
SHOW_OPTION_YES)
-#endif
(void)thd->binlog_flush_pending_rows_event(TRUE);
mysql_unlock_tables(thd, thd->lock);
thd->lock=0;
</patch>
What do you think?
Best,
Nirbhay
After seeing the results from buildbot and crash on optimize table, I think your fix is better.
innodb.innodb_mysql 'innodb_plugin' w2 [ fail ]
|
Test ended at 2013-12-07 20:52:12
|
|
CURRENT_TEST: innodb.innodb_mysql
|
mysqltest: In included file "./include/mix1.inc":
|
included from /usr/local/mariadb-galera-5.5.34-linux-x86_64/mysql-test/suite/innodb/t/innodb_mysql.test at line 20:
|
At line 578: query 'OPTIMIZE TABLE t2' failed: 2013: Lost connection to MySQL server during query
|
|
The result from queries just before the failure was:
|
< snip >
|
INSERT INTO t1(stat_id,acct_id) SELECT stat_id, mod(id+100000, acct_id) FROM t1;
|
INSERT INTO t1(stat_id,acct_id) SELECT stat_id, mod(id+100000, acct_id) FROM t1;
|
INSERT INTO t1(stat_id,acct_id) SELECT stat_id, mod(id+100000, acct_id) FROM t1;
|
INSERT INTO t1(stat_id,acct_id) SELECT stat_id, mod(id+100000, acct_id) FROM t1;
|
UPDATE t1 SET acct_id=785
|
WHERE MOD(stat_id,2)=0 AND MOD(id,stat_id)=MOD(acct_id,stat_id);
|
OPTIMIZE TABLE t1;
|
Table Op Msg_type Msg_text
|
test.t1 optimize status OK
|
SELECT COUNT(*) FROM t1;
|
COUNT(*)
|
40960
|
SELECT COUNT(*) FROM t1 WHERE acct_id=785;
|
COUNT(*)
|
8702
|
EXPLAIN SELECT COUNT(*) FROM t1 WHERE stat_id IN (1,3) AND acct_id=785;
|
id select_type table type possible_keys key key_len ref rows Extra
|
1 SIMPLE t1 range idx1,idx2 idx1 9 NULL 2 Using where; Using index
|
INSERT INTO t2 SELECT * FROM t1;
|
OPTIMIZE TABLE t2;
|
|
More results from queries before failure can be found in /dev/shm/var_auto_zuwb/2/log/innodb_mysql.log
|
|
|
Server [mysqld.1 - pid: 2855, winpid: 2855, exit: 256] failed during test run
|
Server log from this test:
|
----------SERVER LOG START-----------
|
131207 20:52:05 [Note] Plugin 'XTRADB_ADMIN_COMMAND' is disabled.
|
131207 20:52:05 [Note] Plugin 'FEDERATED' is disabled.
|
131207 20:52:05 [Note] Plugin 'ARCHIVE' is disabled.
|
131207 20:52:05 [Note] Plugin 'BLACKHOLE' is disabled.
|
131207 20:52:05 [Note] Plugin 'FEEDBACK' is disabled.
|
131207 20:52:05 [Note] Plugin 'partition' is disabled.
|
131207 20:52:05 [Note] Plugin 'INNODB_LOCK_WAITS' is disabled.
|
131207 20:52:05 [Note] Plugin 'INNODB_CMP' is disabled.
|
131207 20:52:05 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
|
131207 20:52:05 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
|
131207 20:52:05 InnoDB: The InnoDB memory heap is disabled
|
131207 20:52:05 InnoDB: Mutexes and rw_locks use GCC atomic builtins
|
131207 20:52:05 InnoDB: Compressed tables use zlib 1.2.3
|
131207 20:52:05 InnoDB: Using Linux native AIO
|
131207 20:52:05 InnoDB: Error: Linux Native AIO is not supported on tmpdir.
|
InnoDB: You can either move tmpdir to a file system that supports native AIO
|
InnoDB: or you can set innodb_use_native_aio to FALSE to avoid this message.
|
131207 20:52:05 InnoDB: Error: Linux Native AIO check on tmpdir returned error[22]
|
131207 20:52:05 InnoDB: Warning: Linux Native AIO disabled.
|
131207 20:52:05 InnoDB: Initializing buffer pool, size = 8.0M
|
131207 20:52:05 InnoDB: Completed initialization of buffer pool
|
InnoDB: The first specified data file ./ibdata1 did not exist:
|
InnoDB: a new database to be created!
|
131207 20:52:05 InnoDB: Setting file ./ibdata1 size to 10 MB
|
InnoDB: Database physically writes the file full: wait...
|
131207 20:52:05 InnoDB: Log file ./ib_logfile0 did not exist: new to be created
|
InnoDB: Setting log file ./ib_logfile0 size to 5 MB
|
InnoDB: Database physically writes the file full: wait...
|
131207 20:52:05 InnoDB: Log file ./ib_logfile1 did not exist: new to be created
|
InnoDB: Setting log file ./ib_logfile1 size to 5 MB
|
InnoDB: Database physically writes the file full: wait...
|
InnoDB: Doublewrite buffer not found: creating new
|
InnoDB: Doublewrite buffer created
|
InnoDB: 127 rollback segment(s) active.
|
InnoDB: Creating foreign key constraint system tables
|
InnoDB: Foreign key constraint system tables created
|
131207 20:52:05 InnoDB: 5.5.34-MariaDB started; log sequence number 0
|
131207 20:52:05 [Warning] /usr/local/mariadb-galera-5.5.34-linux-x86_64/bin/mysqld: unknown option '--loose-skip-innodb-buffer-pool-pages'
|
131207 20:52:05 [Warning] /usr/local/mariadb-galera-5.5.34-linux-x86_64/bin/mysqld: unknown option '--loose-skip-innodb-buffer-pool-pages-blob'
|
131207 20:52:05 [Warning] /usr/local/mariadb-galera-5.5.34-linux-x86_64/bin/mysqld: unknown option '--loose-skip-innodb-buffer-pool-pages-index'
|
131207 20:52:05 [Warning] /usr/local/mariadb-galera-5.5.34-linux-x86_64/bin/mysqld: unknown option '--loose-skip-innodb-changed-pages'
|
131207 20:52:05 [Warning] /usr/local/mariadb-galera-5.5.34-linux-x86_64/bin/mysqld: unknown option '--loose-skip-innodb-index-stats'
|
131207 20:52:05 [Warning] /usr/local/mariadb-galera-5.5.34-linux-x86_64/bin/mysqld: unknown option '--loose-skip-innodb-rseg'
|
131207 20:52:05 [Warning] /usr/local/mariadb-galera-5.5.34-linux-x86_64/bin/mysqld: unknown option '--loose-skip-innodb-sys-columns'
|
131207 20:52:05 [Warning] /usr/local/mariadb-galera-5.5.34-linux-x86_64/bin/mysqld: unknown option '--loose-skip-innodb-sys-fields'
|
131207 20:52:05 [Warning] /usr/local/mariadb-galera-5.5.34-linux-x86_64/bin/mysqld: unknown option '--loose-skip-innodb-sys-foreign'
|
131207 20:52:05 [Warning] /usr/local/mariadb-galera-5.5.34-linux-x86_64/bin/mysqld: unknown option '--loose-skip-innodb-sys-foreign-cols'
|
131207 20:52:05 [Warning] /usr/local/mariadb-galera-5.5.34-linux-x86_64/bin/mysqld: unknown option '--loose-skip-innodb-sys-indexes'
|
131207 20:52:05 [Warning] /usr/local/mariadb-galera-5.5.34-linux-x86_64/bin/mysqld: unknown option '--loose-skip-innodb-sys-stats'
|
131207 20:52:05 [Warning] /usr/local/mariadb-galera-5.5.34-linux-x86_64/bin/mysqld: unknown option '--loose-skip-innodb-sys-tables'
|
131207 20:52:05 [Warning] /usr/local/mariadb-galera-5.5.34-linux-x86_64/bin/mysqld: unknown option '--loose-skip-innodb-sys-tablestats'
|
131207 20:52:05 [Warning] /usr/local/mariadb-galera-5.5.34-linux-x86_64/bin/mysqld: unknown option '--loose-skip-innodb-table-stats'
|
131207 20:52:05 [Warning] /usr/local/mariadb-galera-5.5.34-linux-x86_64/bin/mysqld: unknown option '--loose-skip-innodb-undo-logs'
|
131207 20:52:05 [Warning] /usr/local/mariadb-galera-5.5.34-linux-x86_64/bin/mysqld: unknown variable 'loose-debug-sync-timeout=300'
|
131207 20:52:05 [Note] Server socket created on IP: '::'.
|
131207 20:52:05 [Note] Event Scheduler: Loaded 0 events
|
131207 20:52:05 [Note] WSREP: Read nil XID from storage engines, skipping position init
|
131207 20:52:05 [Note] WSREP: wsrep_load(): loading provider library 'none'
|
131207 20:52:05 [Note] /usr/local/mariadb-galera-5.5.34-linux-x86_64/bin/mysqld: ready for connections.
|
Version: '5.5.34-MariaDB-wsrep-log' socket: '/usr/local/mariadb-galera-5.5.34-linux-x86_64/mysql-test/var/tmp/2/mysqld.1.sock' port: 16020 MariaDB Server, wsrep_23.7.6
|
131207 20:52:12 [ERROR] 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.
|
|
To report this bug, see http://kb.askmonty.org/en/reporting-bugs
|
|
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.
|
|
Server version: 5.5.34-MariaDB-wsrep-log
|
key_buffer_size=1048576
|
read_buffer_size=131072
|
max_used_connections=3
|
max_threads=153
|
thread_count=1
|
It is possible that mysqld could use up to
|
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 62553 K bytes of memory
|
Hope that's ok; if not, decrease some variables in the equation.
|
|
Thread pointer: 0x0x7fed9c064000
|
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 = 0x4006b068 thread_stack 0x48000
|
/usr/local/mariadb-galera-5.5.34-linux-x86_64/bin/mysqld(my_print_stacktrace+0x2e)[0xb2ea6e]
|
/usr/local/mariadb-galera-5.5.34-linux-x86_64/bin/mysqld(handle_fatal_signal+0x422)[0x70b092]
|
/lib/libpthread.so.0[0x7feda28fb7d0]
|
/usr/local/mariadb-galera-5.5.34-linux-x86_64/bin/mysqld(thd_get_ha_data+0xb)[0x564c8b]
|
/usr/local/mariadb-galera-5.5.34-linux-x86_64/bin/mysqld(_Z13get_trans_logP3THD+0x31)[0x7c5c11]
|
/usr/local/mariadb-galera-5.5.34-linux-x86_64/bin/mysqld(_Z22wsrep_run_wsrep_commitP3THDP10handlertonb+0x82e)[0x6a947e]
|
/usr/local/mariadb-galera-5.5.34-linux-x86_64/lib/plugin/ha_innodb.so[0x7fed9d53e467]
|
/usr/local/mariadb-galera-5.5.34-linux-x86_64/bin/mysqld(_ZN7handler12ha_write_rowEPh+0xba)[0x71043a]
|
/usr/local/mariadb-galera-5.5.34-linux-x86_64/bin/mysqld[0x613029]
|
/usr/local/mariadb-galera-5.5.34-linux-x86_64/bin/mysqld(_Z17mysql_alter_tableP3THDPcS1_P24st_ha_create_informationP10TABLE_LISTP10Alter_infojP8st_orderbb+0x1a35)[0x61b5d5]
|
/usr/local/mariadb-galera-5.5.34-linux-x86_64/bin/mysqld(_Z20mysql_recreate_tableP3THDP10TABLE_LIST+0x18c)[0x61c41c]
|
/usr/local/mariadb-galera-5.5.34-linux-x86_64/bin/mysqld[0x670de1]
|
/usr/local/mariadb-galera-5.5.34-linux-x86_64/bin/mysqld[0x67200b]
|
/usr/local/mariadb-galera-5.5.34-linux-x86_64/bin/mysqld(_ZN24Optimize_table_statement7executeEP3THD+0xde)[0x672aee]
|
/usr/local/mariadb-galera-5.5.34-linux-x86_64/bin/mysqld(_Z21mysql_execute_commandP3THD+0x92c)[0x59ba4c]
|
/usr/local/mariadb-galera-5.5.34-linux-x86_64/bin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x1b0)[0x5a3070]
|
/usr/local/mariadb-galera-5.5.34-linux-x86_64/bin/mysqld[0x5a4949]
|
/usr/local/mariadb-galera-5.5.34-linux-x86_64/bin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x1b92)[0x5a6aa2]
|
/usr/local/mariadb-galera-5.5.34-linux-x86_64/bin/mysqld(_Z10do_commandP3THD+0x278)[0x5a7788]
|
/usr/local/mariadb-galera-5.5.34-linux-x86_64/bin/mysqld(_Z24do_handle_one_connectionP3THD+0x1c3)[0x664843]
|
/usr/local/mariadb-galera-5.5.34-linux-x86_64/bin/mysqld(handle_one_connection+0x4c)[0x664a1c]
|
/usr/local/mariadb-galera-5.5.34-linux-x86_64/bin/mysqld[0xaa21a8]
|
/lib/libpthread.so.0[0x7feda28f33f7]
|
/lib/libc.so.6(clone+0x6d)[0x7feda1a91b3d]
|
|
Trying to get some variables.
|
Some pointers may be invalid and cause the dump to abort.
|
Query (0x7fed9a41d018): OPTIMIZE TABLE t2
|
Connection ID (thread ID): 2
|
Status: NOT_KILLED
|
|
Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=off
|
|
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.
|
Writing a core file
|
There is something wrong with revision 3439. With revision 3438 above test passes but not with 3439. Trying to investigate...