Assert in Diagnostics_area::sql_errno()

[Seppo Jaakola]

Running high conflict rate load against 2 node cluster causes assert with current 5.1.37 merged trunk version.

Here is the assert:
mysqld: sql_class.h:1178: uint Diagnostics_area::sql_errno() const: Assertion `m_status == DA_ERROR' failed.
090906 11:44:08 - mysqld got signal 6 ;

Load is 70/30 update transactions for one table with 10 rows.

Here is load:
 ~/sqlgen --user=root --password=rootpass --port=3306 --host=ardennes --host=batak --create=0 --tables=1 --rows=10 --selects=70 --updates=30 --duration=20 --trans-min=1 --trans-max=5 --users=8

[Seppo Jaakola (seppo-jaakola)]

Here is debug level log from asserting node:

WSREP BF kill, with seqno: 41069
090906 11:44:08 [Warning] Aborting query: UPDATE comm00 SET x = (x + 1) % 65537,
 y = ((y*x % 65537) + (54078*y % 65537) + (y*z % 65537)) % 65537, z = ((z*x % 65
537) + (z*y % 65537) + (54078*z % 65537)) % 65537, r = 0.898559 WHERE p = 9
090906 11:44:08 [Note] WSREP kill trx QUERY_EXEC for 164679
090906 11:44:08 [Warning] WSREP kill query for: -1499456624
090906 11:44:08 [Note] DEBUG: mm_galera.c:mm_galera_post_rollback():1460: trx st
ate: 0 at galera_rolledback for: 9223372036854775807
090906 11:44:08 [Note] WSREP in dispatch_command, aborting UPDATE comm00 SET x =
 (x + 1) % 65537, y = ((y*x % 65537) + (54078*y % 65537) + (y*z % 65537)) % 6553
7, z = ((z*x % 65537) + (z*y % 65537) + (54078*z % 65537)) % 65537, r = 0.898559
 WHERE p = 9
090906 11:44:08 [Note] DEBUG: mm_galera.c:mm_galera_post_rollback():1460: trx st
ate: 0 at galera_rolledback for: 9223372036854775807
mysqld: sql_class.h:1178: uint Diagnostics_area::sql_errno() const: Assertion `m
_status == DA_ERROR' failed.
090906 11:44:08 - 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.
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=8384512
read_buffer_size=131072
max_used_connections=10
max_threads=151
threads_connected=6
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 337751 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd: 0xa912d80
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...
090906 11:44:08 [Note] DEBUG: mm_galera.c:process_query_write_set_applying():856
: GALERA ws commit for: 46424 41069
090906 11:44:08 [Note] DEBUG: galera_job_queue.c:job_queue_end_job():189: job: 0
 complete
090906 11:44:08 [Note] DEBUG: mm_galera.c:mm_galera_recv():1223: worker: 0 with
seqno: (46425 - 41070) type: GCS_ACT_TORDERED recvd
090906 11:44:08 [Note] DEBUG: mm_galera.c:process_query_write_set():904: remote
trx seqno: 46425 41070 last_seen_trx: 46424 46425, cert: 0
090906 11:44:08 [Note] DEBUG: galera_job_queue.c:job_queue_start_job():146: job:
 0 starting
090906 11:44:08 [Note] DEBUG: mm_galera.c:process_query_write_set_applying():856
: GALERA ws commit for: 46425 41070
090906 11:44:08 [Note] DEBUG: galera_job_queue.c:job_queue_end_job():189: job: 0
 complete
090906 11:44:08 [Note] DEBUG: mm_galera.c:mm_galera_pre_commit():1559: trx is mi
ssing from galera: 164690
090906 11:44:08 [Note] DEBUG: mm_galera.c:mm_galera_recv():1223: worker: 0 with
seqno: (46426 - 41071) type: GCS_ACT_TORDERED recvd
090906 11:44:08 [Note] DEBUG: local.c:read_next_block():612: could not read full
 cache block, last:20802 cur:20802
090906 11:44:08 [Note] DEBUG: local.c:read_next_block():612: c...

[Seppo Jaakola (seppo-jaakola)]

A hand crafted debug build can catch the problem in gdb session, here is the trace:

Breakpoint 1, Diagnostics_area::sql_errno (this=0xa6b2f4c0) at sql_class.h:1180
1180 sql_class.h: No such file or directory.
 in sql_class.h
(gdb) bt
#0 Diagnostics_area::sql_errno (this=0xa6b2f4c0) at sql_class.h:1180
#1 0x08396b6c in ha_rollback_trans (thd=0xa6b2e708, all=true)
    at handler.cc:1312
#2 0x0825f288 in end_trans (thd=0xa6b2e708, completion=ROLLBACK)
    at sql_parse.cc:767
#3 0x0826f7b4 in dispatch_command (command=COM_QUERY, thd=0xa6b2e708,
    packet=0xa6b08c09 "UPDATE comm00 SET x = (x + 1) % 65537, y = ((y*x % 65537) + (2528*y % 65537) + (y*z % 65537)) % 65537, z = ((z*x % 65537) + (z*y % 65537) + (2528*z % 65537)) % 65537, r = 0.027815 WHERE p = 3", packet_length=191)
    at sql_parse.cc:1761
#4 0x082706c8 in do_command (thd=0xa6b2e708) at sql_parse.cc:947
#5 0x08257e1c in handle_one_connection (arg=0xa6b2e708) at sql_connect.cc:1155
#6 0x002fe4d2 in start_thread () from /lib/i686/nosegneg/libpthread.so.0
#7 0x0025448e in clone () from /lib/i686/nosegneg/libc.so.6
(gdb) p m_status
$1 = Diagnostics_area::DA_EMPTY
(gdb) p m_sql_errno
$2 = 1317

[Seppo Jaakola (seppo-jaakola)]

(gdb) p thd->killed
$3 = THD::KILL_QUERY

(gdb) p thd->main_da
$5 = {
  is_sent = false,
  can_overwrite_status = false,
  m_message = "Query execution was interrupted\000nings: 0\000", '�' <repeats 471 times>,
  m_sql_errno = 1317,
  m_server_status = 3,
  m_affected_rows = 1,
  m_last_insert_id = 0,
  m_total_warn_count = 0,
  m_status = Diagnostics_area::DA_EMPTY
}