virtual THD::~THD(): Assertion `timer == __null' failed in sql_class.cc:1799 | abort (sig=6) in THD::~THD

Bug #1370002 reported by Roel Van de Paar on 2014-09-16
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona Server moved to https://jira.percona.com/projects/PS
Fix Released
Medium
Laurynas Biveinis
5.1
Invalid
Undecided
Unassigned
5.5
Invalid
Undecided
Unassigned
5.6
Fix Released
Medium
Laurynas Biveinis

Bug Description

Version: '5.6.20-68.0-debug' socket: '/sda/Percona-Server-5.6.20-rel68.0-657.Linux.x86_64-debug/socket.sock' port: 10480 Percona Server (GPL), Release 68.0,Revision 657, DEBUG BINARY
mysqld: /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/sql/sql_class.cc:1799: virtual THD::~THD(): Assertion `timer == __null' failed.
21:13:08 UTC - mysqld got signal 6 ;

(gdb) bt
#0 0x00007f3eaea18771 in pthread_kill () from /lib64/libpthread.so.0
#1 0x0000000000ab09a2 in my_write_core (sig=6) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/mysys/
stacktrace.c:422
#2 0x000000000072ca03 in handle_fatal_signal (sig=6) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.6.20-68.0/
sql/signal_handler.cc:236
#3 <signal handler called>
#4 0x00007f3ead61c989 in raise () from /lib64/libc.so.6
#5 0x00007f3ead61e098 in abort () from /lib64/libc.so.6
#6 0x00007f3ead6158f6 in __assert_fail_base () from /lib64/libc.so.6
#7 0x00007f3ead6159a2 in __assert_fail () from /lib64/libc.so.6
#8 0x0000000000794351 in THD::~THD (this=0x7f3dffaa2000, __in_chrg=<optimized out>) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6
-64/percona-server-5.6.20-68.0/sql/sql_class.cc:1799
#9 0x0000000000794886 in THD::~THD (this=0x7f3dffaa2000, __in_chrg=<optimized out>) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6
-64/percona-server-5.6.20-68.0/sql/sql_class.cc:1840
#10 0x000000000062188a in one_thread_per_connection_end (thd=0x7f3dffaa2000, block_pthread=true) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label
_exp/centos6-64/percona-server-5.6.20-68.0/sql/mysqld.cc:2844
#11 0x00000000007a358c in do_handle_one_connection (thd_arg=0x7f3dffaa2000) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/perco
na-server-5.6.20-68.0/sql/sql_connect.cc:1546
#12 0x00000000007a2fdd in handle_one_connection (arg=0x7f3dffaa2000) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-serv
er-5.6.20-68.0/sql/sql_connect.cc:1443
#13 0x0000000000dbdbb8 in pfs_spawn_thread (arg=0x7f3e927c9f20) at /mnt/workspace/percona-server-5.6-binaries-debug-yassl/label_exp/centos6-64/percona-server-5.
6.20-68.0/storage/perfschema/pfs.cc:1860
#14 0x00007f3eaea13df3 in start_thread () from /lib64/libpthread.so.0
#15 0x00007f3ead6dd3dd in clone () from /lib64/libc.so.6

Roel Van de Paar (roel11) wrote :

=============== Server version
Percona-Server-5.6.20-rel68.0-657.Linux.x86_64-debug

=============== Testcase:
DROP DATABASE test;CREATE DATABASE test;USE test;
XA START'';
SET @@session.max_statement_time=65535;
create table t2(a int,b int,c int,d int,primary key(a,b),unique(d)) engine innodb partition by key(a);

Then - importantly - exit the client (no visible CLI signs), and check error log. Testcase is likely sporadic, bug highly reproducible.

summary: virtual THD::~THD(): Assertion `timer == __null' failed in
- sql_class.cc:1799
+ sql_class.cc:1799 | abort (sig=6) in THD::~THD

MTR:

--source include/count_sessions.inc

--connect(con1,localhost,root,,)

XA START '';
SET @@session.max_statement_time=65535;
--error ER_XAER_RMFAIL
CREATE TABLE t1(a INT);
--disconnect con1

--connection default
--source include/wait_until_count_sessions.inc

This is caused by

int
mysql_execute_command(...)
{
...
  bool reset_timer= set_statement_timer(thd);
...
  DBUG_RETURN(...)
...
error:
...
finish:
...
  if (reset_timer)
    reset_statement_timer(thd);
...
}

where an early DBUG_RETURN (in this instance coming from a check whether a statement will cause an implicit commit in a XA transaction) will skip the reset.

There are more instances of DBUG_RETURN like that instead of goto error. Besides the current bug, they also appear to skip the restore of per-statement variables, which might be a bug too.

MTR for another early DBUG_RETURN

-master.opt: --enforce-gtid-consistency

--source include/count_sessions.inc

--connect(con1,localhost,root,,)

BEGIN;
SET @@session.max_statement_time=65535;
--error ER_GTID_UNSAFE_CREATE_DROP_TEMPORARY_TABLE_IN_TRANSACTION
CREATE TEMPORARY TABLE t1(a INT);
--disconnect con1

--connection default
--source include/wait_until_count_sessions.inc

Roel Van de Paar (roel11) wrote :

Another testcase

DROP DATABASE test;CREATE DATABASE test;USE test;
XA START'';
SET @@SESSION.max_statement_time=10;
drop table b15776;

Roel Van de Paar (roel11) wrote :

This bug is ending a lot of our QA trials. Adding qablock and requesting High triage. Laurynas, if this is an easy fix, it would be appreciated! Thank you

tags: added: qablock
Roel Van de Paar (roel11) wrote :

I can try and generate some more testcases if you think there are more cases that this could happen.

The triage of this bug is Medium, as it's only error paths affected (i.e. the workaround is easy as in "don't make that error")

We can try fixing it sooner than later. Indeed there are more cases when this can happen, so new testcases might help.

Roel Van de Paar (roel11) wrote :

Out of 100+ trials, here are 15 randomly selected & reduced testcases. They all look very similar, but I'll let you decide on what are duplicates or not. Each line is one seperate testcase. Having this fixed would be great as it means that many trials will not be stopped out with this bug.

DROP DATABASE test;CREATE DATABASE test;USE test;xa start'','';SET @@max_statement_time=10000;DROP TABLE t1;

DROP DATABASE test;CREATE DATABASE test;USE test;SET @@SESSION.max_statement_time=10;XA START'';DROP TABLE t1;

DROP DATABASE test;CREATE DATABASE test;USE test;SET max_statement_time=10000;XA START'';CREATE TABLE t1(c1 INT KEY)Engine=TokuDB;

DROP DATABASE test;CREATE DATABASE test;USE test;SET @@session.max_statement_time=TRUE;XA START'';CREATE TABLE t1(c1 INT KEY)Engine=FEDERATED;

DROP DATABASE test;CREATE DATABASE test;USE test;xa start'','';SET @@SESSION.max_statement_time=10;CREATE TABLE t1(c1 INT KEY)Engine=InnoDB;

DROP DATABASE test;CREATE DATABASE test;USE test;SET @@max_statement_time=10000;XA START'';DROP TABLE t1;

DROP DATABASE test;CREATE DATABASE test;USE test;XA START'';SET @@SESSION.max_statement_time=500;DROP TABLE t1;

DROP DATABASE test;CREATE DATABASE test;USE test;SET @@session.max_statement_time=TRUE;XA START'';DROP TABLE t1;

DROP DATABASE test;CREATE DATABASE test;USE test;XA START'';SET @@session.max_statement_time=65535;CREATE TABLE t1(c1 BLOB);

DROP DATABASE test;CREATE DATABASE test;USE test;XA START'';SET @@max_statement_time=10000;create TABLE t1(f1 INT,key k1 (f1)) engine=innodb;

DROP DATABASE test;CREATE DATABASE test;USE test;SET @@session.max_statement_time=65535;XA START'';CREATE TABLE t1(c1 INT KEY)Engine=TokuDB;

DROP DATABASE test;CREATE DATABASE test;USE test;xa start 'test1';SET max_statement_time=10000;DROP TABLE t3;

DROP DATABASE test;CREATE DATABASE test;USE test;XA START'';SET @@session.max_statement_time=10000;DROP TABLE t1;

DROP DATABASE test;CREATE DATABASE test;USE test;XA START 'test1';SET @@SESSION.max_statement_time=10;DROP TABLE t3;

DROP DATABASE test;CREATE DATABASE test;USE test;SET @@session.max_statement_time=50050;xa start 'test-bad';CREATE TABLE t1(c1 INT)Engine=ARCHIVE;

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

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

Other bug subscribers