Percona Server moved to https://jira.percona.com/projects/PS

/sql/protocol.cc:518: void Protocol::end_statement(): Assertion `0' failed | abort (sig=6) in Protocol::end_statement | Seen on UPDATE IGNORE queries

  1. Series 5.6
  2. Bug #1168265
Bug #1168265 reported by Roel Van de Paar
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
MySQL Server
Unknown
Unknown
Percona Server moved to https://jira.percona.com/projects/PS
Status tracked in 5.7
5.1
Won't Fix
Undecided
Unassigned
5.5
Triaged
High
Unassigned
5.6
Triaged
High
Unassigned
5.7
Invalid
Undecided
Unassigned

Bug Description

Seeing many Protocol::end_statement(): Assertions in PS. Debugging w/ Laurynas. Example:

(gdb) bt
#0 0x000000333d00c69c in pthread_kill () from /lib64/libpthread.so.0
#1 0x00000000007e7909 in my_write_core (sig=6) at /ssd/5.5/Percona-Server-5.5.29-rel30.0/mysys/stacktrace.c:433
#2 0x00000000006aff35 in handle_fatal_signal (sig=6) at /ssd/5.5/Percona-Server-5.5.29-rel30.0/sql/signal_handler.cc:250
#3 <signal handler called>
#4 0x000000333cc328a5 in raise () from /lib64/libc.so.6
#5 0x000000333cc34085 in abort () from /lib64/libc.so.6
#6 0x000000333cc2ba1e in __assert_fail_base () from /lib64/libc.so.6
#7 0x000000333cc2bae0 in __assert_fail () from /lib64/libc.so.6
#8 0x0000000000525ce7 in Protocol::end_statement (this=0x38381c0) at /ssd/5.5/Percona-Server-5.5.29-rel30.0/sql/protocol.cc:518
#9 0x00000000005a2e6d in dispatch_command (command=<optimized out>, thd=0x3837cd0, packet=<optimized out>, packet_length=47) at /ssd/5.5/Percona-Server-5.5.29-rel30.0/sql/sql_parse.cc:1433
#10 0x00000000005a3702 in do_command (thd=0x3837cd0) at /ssd/5.5/Percona-Server-5.5.29-rel30.0/sql/sql_parse.cc:789
#11 0x0000000000648f1d in do_handle_one_connection (thd_arg=<optimized out>) at /ssd/5.5/Percona-Server-5.5.29-rel30.0/sql/sql_connect.cc:1489
#12 0x0000000000649010 in handle_one_connection (arg=0x3837cd0) at /ssd/5.5/Percona-Server-5.5.29-rel30.0/sql/sql_connect.cc:1404
#13 0x000000333d007851 in start_thread () from /lib64/libpthread.so.0
#14 0x000000333cce890d in clone () from /lib64/libc.so.6
(gdb) f 10
#10 0x00000000005a3702 in do_command (thd=0x3837cd0) at /ssd/5.5/Percona-Server-5.5.29-rel30.0/sql/sql_parse.cc:789
789 return_value= dispatch_command(command, thd, packet+1, (uint) (packet_length-1));
(gdb) p thd->query_string.string.str
$1 = 0x0

This blocks wide-spread testing of PS using Gypsy.

Revision history for this message
Roel Van de Paar (roel11) wrote :

Likely as-yet unresolved upstream assertion 0 failed bugs

tags: added: upstream
Revision history for this message
Roel Van de Paar (roel11) wrote :
Revision history for this message
Roel Van de Paar (roel11) wrote :

RQG @ 904 <email address hidden>

Revision history for this message
Roel Van de Paar (roel11) wrote :
Revision history for this message
Roel Van de Paar (roel11) wrote :
summary: - Protocol::end_statement(): Assertion `0' failed
+ /sql/protocol.cc:518: void Protocol::end_statement(): Assertion `0'
+ failed | abort (sig=6) in Protocol::end_statement
Revision history for this message
Roel Van de Paar (roel11) wrote : Re: /sql/protocol.cc:518: void Protocol::end_statement(): Assertion `0' failed | abort (sig=6) in Protocol::end_statement

This now blocks 5.6-QA testing. With all the other qablock-ing issues resolved, this one still crashes many trials.

Revision history for this message
Roel Van de Paar (roel11) wrote :

Adding another occurrence with core etc. so that analysis can be made

Revision history for this message
Roel Van de Paar (roel11) wrote :

RQG @ 909 <email address hidden>
PS @ Percona-Server-5.6.13-rc60.5-437-debug.Linux.x86_64 (5.6-QA)

Revision history for this message
Roel Van de Paar (roel11) wrote :
Revision history for this message
Roel Van de Paar (roel11) wrote :
Revision history for this message
Roel Van de Paar (roel11) wrote :
Revision history for this message
Roel Van de Paar (roel11) wrote :
Revision history for this message
Roel Van de Paar (roel11) wrote :
Revision history for this message
Roel Van de Paar (roel11) wrote :
Revision history for this message
Roel Van de Paar (roel11) wrote :

Some further research shows this to always be on UPDATE IGNORE queries.

Query (7f4a5c3dc190): UPDATE IGNORE `table500_innodb_default_int` t1, `table500_innodb_compressed` t2 SET t1.`c15` = '07:20:45.059079' WHERE t1.`c13` <= '2009-08-24 14:34:27.013239'
Query (7fe6fc0b6200): UPDATE IGNORE `table100_innodb_compressed_int_autoinc` t1, `table100_innodb_dynamic_int` t2 SET t1.`c11` = 0 WHERE t1.`c5` <> 154368
Query (7f6c5c19e230): UPDATE IGNORE `table500_innodb_dynamic_int` t1, `table500_innodb_default` t2 SET t1.`c4` = '2005-11-14' WHERE t1.`c13` <= NULL
Query (7fc0d40574c0): UPDATE LOW_PRIORITY IGNORE `table500_innodb_dynamic_int_autoinc` t1, `table500_innodb_compressed_key_pk_parts_2_int_autoinc` t2 SET t1.`c7` = NULL WHERE t1.`c9` = '2005-02-21 12:55:37.061458'
Query (7f6c5c19e230): UPDATE IGNORE `table500_innodb_dynamic_int` t1, `table500_innodb_default` t2 SET t1.`c4` = '2005-11-14' WHERE t1.`c13` <= NULL
Query (7fc0d40574c0): UPDATE LOW_PRIORITY IGNORE `table500_innodb_dynamic_int_autoinc` t1, `table500_innodb_compressed_key_pk_parts_2_int_autoinc` t2 SET t1.`c7` = NULL WHERE t1.`c9` = '2005-02-21 12:55:37.061458'
Query (7f38fc004c10): UPDATE IGNORE `table100_innodb_default_key_pk_parts_2_int_autoinc` t1, `table500_innodb_compressed_int` t2 SET t1.`c16` = -4449792 WHERE t1.`c2` >= 'v'
Query (7f4a5c3dc190): UPDATE IGNORE `table500_innodb_default_int` t1, `table500_innodb_compressed` t2 SET t1.`c15` = '07:20:45.059079' WHERE t1.`c13` <= '2009-08-24 14:34:27.013239'
Query (7fc0d40574c0): UPDATE LOW_PRIORITY IGNORE `table500_innodb_dynamic_int_autoinc` t1, `table500_innodb_compressed_key_pk_parts_2_int_autoinc` t2 SET t1.`c7` = NULL WHERE t1.`c9` = '2005-02-21 12:55:37.061458'

summary: /sql/protocol.cc:518: void Protocol::end_statement(): Assertion `0'
- failed | abort (sig=6) in Protocol::end_statement
+ failed | abort (sig=6) in Protocol::end_statement | Seen on UPDATE
+ IGNORE queries
Revision history for this message
Roel Van de Paar (roel11) wrote :

Worked around ftm by removing "IGNORE" clause from yy grammars.

Roel Van de Paar (roel11)
tags: removed: qablock
Revision history for this message
Raghavendra D Prabhu (raghavendra-prabhu) wrote :

@Roel,

Yes, the IGNORE is what is causing the issue since in our case (PXC), it was hitting with "DELETE IGNORE" as in https://bugs.launchpad.net/percona-xtradb-cluster/+bug/1210509 (may be there was UPDATE IGNORE too before but it isn't in the bug).

Revision history for this message
Roel Van de Paar (roel11) wrote :

This bug may be 56qual even if 5.5 is affected: the 5.6 assertion 0 may have been for a different query (or even for multiple different queries) where as the 5.6 seen assertion 0 is clearly limited to the UPDATE IGNORE queries. Maybe the next step would be to establish if the UPDATE IGNORE issue (at least) is 1) in 5.5 also, 2) upstream or 3) benign. Any of these 3 would mean we can remove 56qual tag.

tags: added: 56qual
Revision history for this message
Raghavendra D Prabhu (raghavendra-prabhu) wrote :

Hitting this with 'DELETE IGNORE' again.

Query (7f517c004c50): DELETE IGNORE FROM `table1000_innodb_int` WHERE `col_int_key` IN ( 620298240 , 3424452608 , 214 , 144 , 7 ) ORDER BY `col_char_12`,`col_char_12_key`,`col_int`,`col_int_key`,`pk` LIMIT 3

Revision history for this message
Roel Van de Paar (roel11) wrote :

s/5.6 assertion/5.5 assertion/ in #18

Revision history for this message
Roel Van de Paar (roel11) wrote :

Tried reproducing this in 5.6 by re-enabling IGNORE and temporarily increasing frequency, to no avail. Instead ended up with bug 1234446 which seems unrelated.

Revision history for this message
Ramesh Sivaraman (rameshvs02) wrote :

Seen this issue in PS-5.5. Most of the SERVER CRASH errors are with 'UPDATE IGNORE' query. As per #16, removing "IGNORE" clause from PS 5.5 yy grammar.

Some of the update queries that caused server crash..

Query (7fb54c4472d0): UPDATE IGNORE `view_table500_innodb_compressed_int_autoinc` t1, `table500_innodb_default_int` t2 SET t1.`c6` = -1 WHERE t1.`c10` < '2003-05-09 13:09:40.001516'

Query (7f1774004dd0): UPDATE IGNORE `table500_innodb_compressed_key_pk_parts_2_int` t1, `table500_innodb_compressed_key_pk_parts_2_int_autoinc` t2 SET t1.`c11` = NULL WHERE t1.`c10` < '20041117104500.024739'

Query (7ff3e8004dd0): UPDATE IGNORE `table500_innodb_compressed_key_pk_parts_2_int` t1, `table500_innodb_default_key_pk_parts_2_int` t2 SET t1.`c1` = '20061122143506.002479' WHERE t1.`c18` = 'f'

Query (7ffc6c004dd0): UPDATE IGNORE `table500_innodb_compressed_key_pk_parts_2_int` t1, `table500_innodb_default` t2 SET t1.`c4` = -1 WHERE t1.`c4` != 0

Revision history for this message
Raghavendra D Prabhu (raghavendra-prabhu) wrote :

Easy to replicate this with UNIV_DEBUG + sysbench tests. Hitting this with INSERT IGNORE here.

"As per #16, removing "IGNORE" clause from PS 5.5 yy grammar"

- this can be done but this means IGNORE will never be tested.

tags: added: qablock
Laurynas Biveinis (laurynas-biveinis)
tags: removed: qablock upstream
Revision history for this message
Roel Van de Paar (roel11) wrote :

http://bugs.mysql.com/bug.php?id=74411

tags: added: upstream
Revision history for this message
Shahriyar Rzayev (rzayev-sehriyar) wrote :

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-2934

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.