[Maria-developers] Galera-10.0 still does not work with rollbacks

19 Sep 2013

      Hi,

I need help. After merge galera-10.0 with 10.0, rollback asserts. I seem 
not to be able to find the actual reason. I added some extra output on 
log.cc to dump out the cache_log data from both trx_cache and 
stmt_cache, but to me these values do not really mean anything, here 
some values from the beginning:

I do not follow why those pos values are so big ?

130919  9:25:51 [ERROR] WSREP: ::jan_BINLOG_COMMIT:: TRX: Pending (nil) 
pos 0, pos_in_file 140514620666192 current_pos 140514620731584 
request_pos 140514620731688 write_pos 67383728
130919  9:25:51 [ERROR] WSREP: ::jan_COMMIT:: STMT: STMT: Pending (nil) 
pos 0, pos_in_file 140514620665776 current_pos 140514620698688 
request_pos 140514620698688 write_pos 67383728
130919  9:25:51 [ERROR] WSREP: ::jan_BINLOG_COMMIT_FLUSH_TRX_CACHE:: 
TRX: Pending (nil) pos 0, pos_in_file 140514620666192 current_pos 
140514620731584 request_pos 140514620731688 write_pos 18263408
130919  9:25:51 [ERROR] WSREP: ::jan_BINLOG_COMMIT_FLUSH_TRX_CACHE:: 
STMT: Pending (nil) pos 0, pos_in_file 140514620665776 current_pos 
140514620698688 request_pos 140514620698688 write_pos 18263408
130919  9:25:51 [ERROR] WSREP: ::jan_BINLOG_FLUSH_CACHE:: TRX: Pending 
(nil) pos 0, pos_in_file 140514620666192 current_pos 140514620731584 
request_pos 140514620731688 write_pos 18571483
130919  9:25:51 [ERROR] WSREP: ::jan_BINLOG_FLUSH_CACHE:: STMT: Pending 
(nil) pos 0, pos_in_file 140514620665776 current_pos 140514620698688 
request_pos 140514620698688 write_pos 18571483
130919  9:25:51 [ERROR] WSREP: ::jan_reset:: Pending (nil) pos 0, 
pos_in_file 140514620666240 current_pos 140514620731584 request_pos 
140514620731584 write_pos 140516368466480
130919  9:25:51 [ERROR] WSREP: ::jan_reset:: Pending (nil) pos 0, 
pos_in_file 140514620666240 current_pos 140514620731584 request_pos 
140514620731584 write_pos 11
130919  9:26:03 [ERROR] WSREP: ::jan_BINLOG_COMMIT:: TRX: Pending (nil) 
pos 0, pos_in_file 140514620666192 current_pos 140514620731584 
request_pos 140514620731724 write_pos 67383728
130919  9:26:03 [ERROR] WSREP: ::jan_COMMIT:: STMT: STMT: Pending (nil) 
pos 0, pos_in_file 140514620665776 current_pos 140514620698688 
request_pos 140514620698688 write_pos 67383728
130919  9:26:03 [ERROR] WSREP: ::jan_BINLOG_COMMIT_FLUSH_TRX_CACHE:: 
TRX: Pending (nil) pos 0, pos_in_file 140514620666192 current_pos 
140514620731584 request_pos 140514620731724 write_pos 18263408
130919  9:26:03 [ERROR] WSREP: ::jan_BINLOG_COMMIT_FLUSH_TRX_CACHE:: 
STMT: Pending (nil) pos 0, pos_in_file 140514620665776 current_pos 
140514620698688 request_pos 140514620698688 write_pos 18263408
130919  9:26:03 [ERROR] WSREP: ::jan_BINLOG_FLUSH_CACHE:: TRX: Pending 
(nil) pos 0, pos_in_file 140514620666192 current_pos 140514620731584 
request_pos 140514620731724 write_pos 18571483
130919  9:26:03 [ERROR] WSREP: ::jan_BINLOG_FLUSH_CACHE:: STMT: Pending 
(nil) pos 0, pos_in_file 140514620665776 current_pos 140514620698688 
request_pos 140514620698688 write_pos 18571483
130919  9:26:03 [ERROR] WSREP: ::jan_reset:: Pending (nil) pos 0, 
pos_in_file 140514620666240 current_pos 140514620731584 request_pos 
140514620731584 write_pos 140516368466480
130919  9:26:03 [ERROR] WSREP: ::jan_reset:: Pending (nil) pos 0, 
pos_in_file 140514620666240 current_pos 140514620731584 request_pos 
140514620731584 write_pos 11
130919  9:26:10 [ERROR] WSREP: ::jan_BINLOG_COMMIT:: TRX: Pending (nil) 
pos 0, pos_in_file 140514620666192 current_pos 140514620731584 
request_pos 140514620731706 write_pos 67383728
130919  9:26:10 [ERROR] WSREP: ::jan_COMMIT:: STMT: STMT: Pending (nil) 
pos 0, pos_in_file 140514620665776 current_pos 140514620698688 
request_pos 140514620698688 write_pos 67383728
130919  9:26:10 [ERROR] WSREP: ::jan_BINLOG_COMMIT_FLUSH_TRX_CACHE:: 
TRX: Pending (nil) pos 0, pos_in_file 140514620666192 current_pos 
140514620731584 request_pos 140514620731706 write_pos 18263408
130919  9:26:10 [ERROR] WSREP: ::jan_BINLOG_COMMIT_FLUSH_TRX_CACHE:: 
STMT: Pending (nil) pos 0, pos_in_file 140514620665776 current_pos 
140514620698688 request_pos 140514620698688 write_pos 18263408
130919  9:26:10 [ERROR] WSREP: ::jan_BINLOG_FLUSH_CACHE:: TRX: Pending 
(nil) pos 0, pos_in_file 140514620666192 current_pos 140514620731584 
request_pos 140514620731706 write_pos 18571483
130919  9:26:10 [ERROR] WSREP: ::jan_BINLOG_FLUSH_CACHE:: STMT: Pending 
(nil) pos 0, pos_in_file 140514620665776 current_pos 140514620698688 
request_pos 140514620698688 write_pos 18571483

Still the test assert on the exactly the same place i.e.:

130919  9:28:40 [ERROR] WSREP: ::jan_COMMIT:: STMT: STMT: Pending (nil) 
pos 0, pos_in_file 140514418699920 current_pos 140514418701792 
request_pos 140514418701792 write_pos 140514418513168
130919  9:28:41 [ERROR] WSREP: ::jan_BINLOG_ROLLBACK::TRX: Pending (nil) 
pos 11936128518282651045, pos_in_file 140514418700384 current_pos 
140514418735008 request_pos 140514418738328 write_pos 16516442
130919  9:28:41 [ERROR] WSREP: ::jan_BINLOG_ROLLBACK:: STMT: Pending 
(nil) pos 0, pos_in_file 140514418699920 current_pos 140514418701792 
request_pos 140514418701792 write_pos 16516442
130919  9:28:41 [ERROR] WSREP: ::jan_BINLOG_TRUNCATE_TRX_CACHE:: Pending 
(nil) pos 11936128518282651045, pos_in_file 140514418700384 current_pos 
140514418735008 request_pos 140514418738328 write_pos 140514418494000
130919  9:28:41 [ERROR] WSREP: ::jan_BINLOG_TRUNCATE_TRX_CACHE:: STMT: 
Pending (nil) pos 0, pos_in_file 140514418699920 current_pos 
140514418701792 request_pos 140514418701792 write_pos 140514418494000
130919  9:28:41 [ERROR] WSREP: ::jan_reset:: Pending (nil) pos 
11936128518282651045, pos_in_file 140514418700384 current_pos 
140514418735008 request_pos 140514418738328 write_pos 18571483
mysqld: /home/jan/mysql/galera-10.0/sql/log.cc:295: void 
binlog_cache_data::reset(): Assertion `empty()' failed.
130919  9:28:41 [ERROR] mysqld got signal 6 ;
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: 10.0.4-MariaDB-debug-log
key_buffer_size=134217728
read_buffer_size=131072
max_used_connections=7
max_threads=153
thread_count=7
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 
467201 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x0x4d68d40
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 = 0x7fcc84314e00 thread_stack 0x48000
mysys/stacktrace.c:246(my_print_stacktrace)[0xe3cd92]
sql/signal_handler.cc:155(handle_fatal_signal)[0x867dab]
??:0(??)[0x7fcc96384bd0]
??:0(??)[0x7fcc957d8037]
??:0(??)[0x7fcc957db698]
??:0(??)[0x7fcc957d0e03]
??:0(??)[0x7fcc957d0eb2]
sql/log.cc:296(binlog_cache_data::reset())[0x94a533]
sql/log.cc:464(binlog_cache_mngr::reset(bool, bool))[0x94a8ec]
sql/log.cc:2008(binlog_truncate_trx_cache)[0x936265]
sql/log.cc:2205(binlog_rollback)[0x936d7b]
sql/handler.cc:1600(ha_rollback_trans(THD*, bool))[0x86b625]
sql/transaction.cc:321(trans_rollback(THD*))[0x7a0cbb]
sql/sql_parse.cc:4638(mysql_execute_command(THD*))[0x671889]
sql/sql_parse.cc:6820(mysql_parse(THD*, char*, unsigned int, 
Parser_state*))[0x677d28]
sql/sql_parse.cc:6653(wsrep_mysql_parse)[0x6774a9]
sql/sql_parse.cc:1459(dispatch_command(enum_server_command, THD*, char*, 
unsigned int))[0x6688a4]
sql/sql_parse.cc:1080(do_command(THD*))[0x66787a]
sql/sql_connect.cc:1404(do_handle_one_connection(THD*))[0x78baa9]
sql/sql_connect.cc:1312(handle_one_connection)[0x78b7e9]
perfschema/pfs.cc:1855(pfs_spawn_thread)[0xb0d40e]
??:0(??)[0x7fcc9637cf8e]
??:0(??)[0x7fcc9589ae1d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x7fcc10005288): ROLLBACK
Connection ID (thread ID): 11
Status: NOT_KILLED

--

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>