[Maria-developers] Rollback causes assertion with Galera 10.0
Hi, Background: I merged 10.0 to lp:~maria-captains/maria/maria-10.0-galera/, merge result is pushed to the tree. In testing I hit repeatable to following assertion #0 0x00007f1ff987f037 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56 #1 0x00007f1ff9882698 in __GI_abort () at abort.c:90 #2 0x00007f1ff9877e03 in __assert_fail_base (fmt=0x7f1ff99ce578 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x109b4ff "empty()", file=file@entry=0x109b4d8 "/home/jan/mysql/galera-10.0/sql/log.cc", line=line@entry=294, function=function@entry=0x10a01e0 <binlog_cache_data::reset()::__PRETTY_FUNCTION__> "void binlog_cache_data::reset()") at assert.c:92 #3 0x00007f1ff9877eb2 in __GI___assert_fail (assertion=0x109b4ff "empty()", file=0x109b4d8 "/home/jan/mysql/galera-10.0/sql/log.cc", line=294, function=0x10a01e0 <binlog_cache_data::reset()::__PRETTY_FUNCTION__> "void binlog_cache_data::reset()") at assert.c:101 #4 0x00000000009497d4 in binlog_cache_data::reset (this=0x7f1f7403ad60) at /home/jan/mysql/galera-10.0/sql/log.cc:294 #5 0x0000000000949b6a in binlog_cache_mngr::reset (this=0x7f1f7403ab90, do_stmt=false, do_trx=true) at /home/jan/mysql/galera-10.0/sql/log.cc:462 #6 0x0000000000935a4c in binlog_truncate_trx_cache (thd=0x45b7d40, cache_mngr=0x7f1f7403ab90, all=true) at /home/jan/mysql/galera-10.0/sql/log.cc:1991 #7 0x0000000000936123 in binlog_rollback (hton=0x3891fb0, thd=0x45b7d40, all=true) at /home/jan/mysql/galera-10.0/sql/log.cc:2180 #8 0x000000000086b750 in ha_rollback_trans (thd=0x45b7d40, all=true) at /home/jan/mysql/galera-10.0/sql/handler.cc:1616 #9 0x00000000007a0c5f in trans_rollback (thd=0x45b7d40) at /home/jan/mysql/galera-10.0/sql/transaction.cc:321 #10 0x00000000006718b2 in mysql_execute_command (thd=0x45b7d40) at /home/jan/mysql/galera-10.0/sql/sql_parse.cc:4634 #11 0x0000000000677d52 in mysql_parse (thd=0x45b7d40, rawbuf=0x7f1f74005288 "ROLLBACK", length=8, parser_state=0x7f1fe83bb610) at /home/jan/mysql/galera-10.0/sql/sql_parse.cc:6816 #12 0x00000000006774d3 in wsrep_mysql_parse (thd=0x45b7d40, rawbuf=0x7f1f74005288 "ROLLBACK", length=8, parser_state=0x7f1fe83bb610) at /home/jan/mysql/galera-10.0/sql/sql_parse.cc:6647 #13 0x00000000006688cd in dispatch_command (command=COM_QUERY, thd=0x45b7d40, packet=0x44807c1 "ROLLBACK ", packet_length=9) at /home/jan/mysql/galera-10.0/sql/sql_parse.cc:1451 #14 0x00000000006678a3 in do_command (thd=0x45b7d40) at /home/jan/mysql/galera-10.0/sql/sql_parse.cc:1077 #15 0x000000000078ba4d in do_handle_one_connection (thd_arg=0x45b7d40) at /home/jan/mysql/galera-10.0/sql/sql_connect.cc:1404 #16 0x000000000078b78d in handle_one_connection (arg=0x45b7d40) at /home/jan/mysql/galera-10.0/sql/sql_connect.cc:1311 #17 0x0000000000b0c20a in pfs_spawn_thread (arg=0x45713a0) at /home/jan/mysql/galera-10.0/storage/perfschema/pfs.cc:1853 #18 0x00007f1ffa423f8e in start_thread (arg=0x7f1fe83bc700) at pthread_create.c:311 #19 0x00007f1ff9941e1d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113 (gdb) We go from log.cc::binlog_rollback : else if (ending_trans(thd, all) || (!(thd->variables.option_bits & OPTION_KEEP_LOG) && (!stmt_has_updated_non_trans_table(thd) || WSREP_FORMAT(thd->variables.binlog_format) != BINLOG_FORMAT_STMT) && (!cache_mngr->trx_cache.changes_to_non_trans_temp_table() || WSREP_FORMAT(thd->variables.binlog_format) != BINLOG_FORMAT_MIXED))) error= binlog_truncate_trx_cache(thd, cache_mngr, all); end there to cache_mngr->reset(false, true); and there is DBUG_ASSERT(empty()); bool empty() const { return pending() == NULL && my_b_tell(&cache_log) == 0; } At empty() this is what does not hold : my_b_tell(&cache_log) == 0; // not sure what this means At test output there is at the end: # 2013-09-09T10:03:21 [6620] Query: UPDATE LOW_PRIORITY IGNORE `table100_int_autoinc` AS X SET `col_char_12` = 220 WHERE X . `col_char_12_key` IN ( 2427781120 , 1 , 'i' , 'm' , 'o' ) ORDER BY `col_char_12`,`col_char_12_key`,`col_int`,`col_int_key`,`pk` LIMIT 8 failed: 1213 Deadlock found when trying to get lock; try restarting transaction. Further errors of this kind will be suppressed. # 2013-09-09T10:04:14 [6620] Query: DELETE LOW_PRIORITY IGNORE FROM `table10_key_pk_parts_2_int_autoinc` WHERE `col_char_12_key` IN ( 4200660992 , 1646198784 , 3888709632 , 32 , 'c' ) ORDER BY `col_char_12`,`col_char_12_key`,`col_int`,`col_int_key`,`pk` LIMIT 1 failed: 1205 Lock wait timeout exceeded; try restarting transaction. Further errors of this kind will be suppressed. Unfortunately, general log contains so many statements from different connections that they are not really helpful for getting repeatable test case. R: Jan -- Jan Lindström Principal Engineer MariaDB | MaxScale | skype: jan_p_lindstrom www.skysql.com <http://www.skysql.com/> Twitter <http://twitter.com/skysql> Blog <http://www.skysql.com/blog/> Facebook <http://www.facebook.com/skysql> LinkedIn <http://www.linkedin.com/company/1214250> Google+ <https://plus.google.com/117544963211695643458/posts>
Jan Lindström <jplindst@mariadb.org> writes:
#3 0x00007f1ff9877eb2 in __GI___assert_fail (assertion=0x109b4ff "empty()", file=0x109b4d8 "/home/jan/mysql/galera-10.0/sql/log.cc", line=294, function= 0x10a01e0 <binlog_cache_data::reset()::__PRETTY_FUNCTION__> "void binlog_cache_data::reset()") at assert.c:101 #4 0x00000000009497d4 in binlog_cache_data::reset (this=0x7f1f7403ad60) at / home/jan/mysql/galera-10.0/sql/log.cc:294 #5 0x0000000000949b6a in binlog_cache_mngr::reset (this=0x7f1f7403ab90, do_stmt=false, do_trx=true) at /home/jan/mysql/galera-10.0/sql/log.cc:462 #6 0x0000000000935a4c in binlog_truncate_trx_cache (thd=0x45b7d40, cache_mngr= 0x7f1f7403ab90, all=true) at /home/jan/mysql/galera-10.0/sql/log.cc:1991 #7 0x0000000000936123 in binlog_rollback (hton=0x3891fb0, thd=0x45b7d40, all= true) at /home/jan/mysql/galera-10.0/sql/log.cc:2180
At empty() this is what does not hold : my_b_tell(&cache_log) == 0; // not sure what this means
The cache_log is used first in WRITE_CACHE mode to store events for DML done in a transaction. And then in READ_CACHE mode to read out the events again and copy them into the actual binlog file. I suspect this is some problem with error handling. The binlog code is known to be extremely complicated wrt. error handling, and there are many possibilities for problems when errors turn up in unexpected places. It sounds like you are able to inspect the state at the time of the assert with gdb (running mysqld in the debugger or inspecting a core file). Can you help me by obtaining some additional values that will help me understand how this could have occured? Try in GDB: p cache_log I would like to see what the state of the cache_log is. Of particular interest is the value of cache_log.type (WRITE_CACHE or READ_CACHE?) and the fields pos_in_file, current_pos, and request_pos used in my_b_tell, but better to get all the values. With that info, I will try to analyse further... I suspect this is related to a failure that occurs in an unusual place in galera (conflict causing error during commit or something like that) that either hits a bug in binlog error handling or was done incorrectly in the galera patch. But I need more information about what lead up to this to be sure ... - Kristian.
Hi, This is what I see inspecting the cache_log (gdb) p cache_log $1 = {pos_in_file = 11936128518282651045, end_of_file = 18446744073709547520, read_pos = 0x7f214003bb10 "%\374-R\023", read_end = 0x7f214003bc70 "", buffer = 0x7f214003bb10 "%\374-R\023", request_pos = 0x7f214003bb10 "%\374-R\023", write_buffer = 0x7f214003bb10 "%\374-R\023", append_read_pos = 0x7f214003bb10 "%\374-R\023", write_pos = 0x7f214003c848 "$\374-R\027", write_end = 0x7f214004356b '\245' <repeats 200 times>..., current_pos = 0x7f21400333d0, current_end = 0x7f21400333d8, append_buffer_lock = {m_mutex = {global = {__data = {__lock = 0, __count = 0, __owner = 0, __nusers = 0, __kind = 0, __spins = 0, __list = {__prev = 0x0, __next = 0x0}}, __size = '\000' <repeats 39 times>, __align = 0}, mutex = {__data = {__lock = 0, __count = 0, __owner = 0, __nusers = 0, __kind = 0, __spins = 0, __list = {__prev = 0x0, __next = 0x0}}, __size = '\000' <repeats 39 times>, __align = 0}, file = 0x0, name = 0x0, line = 0, count = 0, create_flags = 0, active_flags = 0, id = 0, thread = 0, locked_mutex = 0x0, used_mutex = 0x0, prev = 0x0, next = 0x0}, m_psi = 0x0}, share = 0x0, read_function = 0xe17c32 <_my_b_read>, write_function = 0xe194d4 <_my_b_write>, type = WRITE_CACHE, pre_read = 0x0, post_read = 0x0, pre_close = 0x0, disk_writes = 0, arg = 0x0, file_name = 0x0, dir = 0x7f214003b9d0 "/home/jan/mysql/galera-test/node0/tmp", prefix = 0x7f214003ba80 "ML", file = 58, seek_not_done = 1, error = -1, buffer_length = 32768, read_length = 32768, myflags = 16, alloced_buffer = 1 '\001'}'' (gdb) p cache_log.current_pos $2 = (uchar **) 0x7f21400333d0 (gdb) p *cache_log.current_pos $3 = (uchar *) 0x7f214003c848 "$\374-R\027" (gdb) p *cache_log.pos_in_file Cannot access memory at address 0xa5a5a5a5a5a5a5a5 (gdb) p cache_log.pos_in_file $4 = 11936128518282651045 (gdb) p *cache_log.request_pos $5 = 37 '%' (gdb) p cache_log.request_pos $6 = (uchar *) 0x7f214003bb10 "%\374-R\023"' R: Jan
Jan Lindström <jplindst@mariadb.org> writes:
#3 0x00007f1ff9877eb2 in __GI___assert_fail (assertion=0x109b4ff "empty()", file=0x109b4d8 "/home/jan/mysql/galera-10.0/sql/log.cc", line=294, function= 0x10a01e0 <binlog_cache_data::reset()::__PRETTY_FUNCTION__> "void binlog_cache_data::reset()") at assert.c:101 #4 0x00000000009497d4 in binlog_cache_data::reset (this=0x7f1f7403ad60) at / home/jan/mysql/galera-10.0/sql/log.cc:294 #5 0x0000000000949b6a in binlog_cache_mngr::reset (this=0x7f1f7403ab90, do_stmt=false, do_trx=true) at /home/jan/mysql/galera-10.0/sql/log.cc:462 #6 0x0000000000935a4c in binlog_truncate_trx_cache (thd=0x45b7d40, cache_mngr= 0x7f1f7403ab90, all=true) at /home/jan/mysql/galera-10.0/sql/log.cc:1991 #7 0x0000000000936123 in binlog_rollback (hton=0x3891fb0, thd=0x45b7d40, all= true) at /home/jan/mysql/galera-10.0/sql/log.cc:2180 At empty() this is what does not hold : my_b_tell(&cache_log) == 0; // not sure what this means The cache_log is used first in WRITE_CACHE mode to store events for DML done in a transaction. And then in READ_CACHE mode to read out the events again and copy them into the actual binlog file.
I suspect this is some problem with error handling. The binlog code is known to be extremely complicated wrt. error handling, and there are many possibilities for problems when errors turn up in unexpected places.
It sounds like you are able to inspect the state at the time of the assert with gdb (running mysqld in the debugger or inspecting a core file). Can you help me by obtaining some additional values that will help me understand how this could have occured?
Try in GDB:
p cache_log
I would like to see what the state of the cache_log is. Of particular interest is the value of cache_log.type (WRITE_CACHE or READ_CACHE?) and the fields pos_in_file, current_pos, and request_pos used in my_b_tell, but better to get all the values.
With that info, I will try to analyse further...
I suspect this is related to a failure that occurs in an unusual place in galera (conflict causing error during commit or something like that) that either hits a bug in binlog error handling or was done incorrectly in the galera patch. But I need more information about what lead up to this to be sure ...
- Kristian.
-- -- Jan Lindström Principal Engineer MariaDB | MaxScale | skype: jan_p_lindstrom www.skysql.com <http://www.skysql.com/> Twitter <http://twitter.com/skysql> Blog <http://www.skysql.com/blog/> Facebook <http://www.facebook.com/skysql> LinkedIn <http://www.linkedin.com/company/1214250> Google+ <https://plus.google.com/117544963211695643458/posts>
Jan Lindström <jplindst@mariadb.org> writes:
(gdb) p cache_log $1 = {pos_in_file = 11936128518282651045, end_of_file = 18446744073709547520,
(gdb) p *cache_log.pos_in_file Cannot access memory at address 0xa5a5a5a5a5a5a5a5
Ouch. That looks like memory corruption :-( Seems something has overwritten the start of cache_log with invalid memory data. 0xa5 is what safe_malloc puts in newly allocated memory, so it is uninitialised data. Are you able to repeat the issue with Valgrind? That would probably be quite useful to pinpoint where the invalid memory access is happening. Another way to get more information is to repeat the error while the server is running with debug trace enabled (--debug=+d). This will generate a _lot_ of output. But given that there is uninitialised memory issues, Valgrind is likely to give more useful info. What are you doing to produce the error? - Kristian.
Hi,
What are you doing to produce the error? - Kristian.
I use the test environment provided by elenst from bzr+ssh://bazaar.launchpad.net/~elenst/randgen/mariadb-patches/ and script : perl ./runall-new.pl --grammar=conf/engines/engine_stress.yy --gendata=conf/engines/engine_stress.zz --duration=600 --queries=100M --threads=4 --galera=mmm --basedir=/home/jan/mysql/galera-10.0 --vardir=/home/jan/mysql/galera-test --mysqld=--wsrep-provider=/usr/lib/libgalera_smm.so --debug --mysqld=--general-log=1 --mysqld=--general_log_file=/home/jan/mysql/galera-test/stmt.log R: -- Jan Lindström Principal Engineer MariaDB | MaxScale | skype: jan_p_lindstrom www.skysql.com <http://www.skysql.com/> Twitter <http://twitter.com/skysql> Blog <http://www.skysql.com/blog/> Facebook <http://www.facebook.com/skysql> LinkedIn <http://www.linkedin.com/company/1214250> Google+ <https://plus.google.com/117544963211695643458/posts>
participants (2)
-
Jan Lindström -
Kristian Nielsen