Assertion `!table || !table->in_use || table->in_use == _current_thd()' failed in ha_thd from sql/handler.cc:2468 on PK drop in ALTER

[Roel Van de Paar]

Thread 1 (LWP 30832):
+bt
#0 0x000000362fa0c69c in pthread_kill () from /lib64/libpthread.so.0
#1 0x00000000006a649f in handle_fatal_signal (sig=6) at /bzr/5.6_dbg/Percona-Server-5.6.14-rel62.0/sql/signal_handler.cc:254
#2 <signal handler called>
#3 0x000000362f2328e5 in raise () from /lib64/libc.so.6
#4 0x000000362f2340c5 in abort () from /lib64/libc.so.6
#5 0x000000362f22ba0e in __assert_fail_base () from /lib64/libc.so.6
#6 0x000000362f22bad0 in __assert_fail () from /lib64/libc.so.6
#7 0x00000000005e35ec in ha_thd (this=0x7f3814044240) at /bzr/5.6_dbg/Percona-Server-5.6.14-rel62.0/sql/handler.cc:2468
#8 handler::ha_thd (this=0x7f3814044240) at /bzr/5.6_dbg/Percona-Server-5.6.14-rel62.0/sql/handler.cc:2466
#9 0x00000000005edc31 in handler::mark_trx_read_write (this=0x7f3814044240) at /bzr/5.6_dbg/Percona-Server-5.6.14-rel62.0/sql/handler.cc:4124
#10 0x00000000005eb218 in handler::ha_write_row (this=0x7f3814044240, buf=0x7f3814009440 <incomplete sequence \374>) at /bzr/5.6_dbg/Percona-Server-5.6.14-rel62.0/sql/handler.cc:7469
#11 0x00000000005ad762 in copy_data_between_tables (from=from@entry=0x7f381404b0b0, to=to@entry=0x7f381404f540, create=..., ignore=ignore@entry=false, order_num=order_num@entry=0, order=order@entry=0x0, copied=copied@entry=0x7f3875ca26c0, deleted=deleted@entry=0x7f3875ca26c8, keys_onoff=Alter_info::LEAVE_AS_IS, alter_ctx=alter_ctx@entry=0x7f3875ca32c0) at /bzr/5.6_dbg/Percona-Server-5.6.14-rel62.0/sql/sql_table.cc:9025
#12 0x000000000078b744 in mysql_alter_table (thd=thd@entry=0x2cc1ef0, new_db=<optimized out>, new_name=0x7f381404f540 "\020\376\004\024\070\177", create_info=create_info@entry=0x7f3875ca3ed0, table_list=table_list@entry=0x7f3814004ff8, alter_info=0x7f381404f540, alter_info@entry=0x7f3875ca3e10, order_num=0, order=0x0, ignore=false) at /bzr/5.6_dbg/Percona-Server-5.6.14-rel62.0/sql/sql_table.cc:8553
#13 0x0000000000886a78 in Sql_cmd_alter_table::execute (this=<optimized out>, thd=0x2cc1ef0) at /bzr/5.6_dbg/Percona-Server-5.6.14-rel62.0/sql/sql_alter.cc:317
#14 0x0000000000731411 in mysql_execute_command (thd=thd@entry=0x2cc1ef0) at /bzr/5.6_dbg/Percona-Server-5.6.14-rel62.0/sql/sql_parse.cc:5287
#15 0x0000000000736c38 in mysql_parse (thd=thd@entry=0x2cc1ef0, rawbuf=<optimized out>, length=<optimized out>, parser_state=parser_state@entry=0x7f3875ca5550) at /bzr/5.6_dbg/Percona-Server-5.6.14-rel62.0/sql/sql_parse.cc:6647
#16 0x0000000000737991 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x2cc1ef0, packet=packet@entry=0x2c9d5b1 "ALTER TABLE query030879 . `t1` DROP COLUMN `pk`", packet_length=packet_length@entry=47) at /bzr/5.6_dbg/Percona-Server-5.6.14-rel62.0/sql/sql_parse.cc:1438
#17 0x00000000007387ab in do_command (thd=thd@entry=0x2cc1ef0) at /bzr/5.6_dbg/Percona-Server-5.6.14-rel62.0/sql/sql_parse.cc:1051
#18 0x00000000007d76e7 in threadpool_process_request (thd=0x2cc1ef0) at /bzr/5.6_dbg/Percona-Server-5.6.14-rel62.0/sql/threadpool_common.cc:313
#19 0x00000000007d891f in handle_event (connection=0x2c408f0) at /bzr/5.6_dbg/Percona-Server-5.6.14-rel62.0/sql/threadpool_unix.cc:1468
#20 worker_main (param=param@entry=0x153ce00 <all_groups+2048>) at /bzr/5.6_dbg/Percona-Server-5.6.14-rel62.0/sql/threadpool_unix.cc:1521
#21 0x00000000009bbd73 in pfs_spawn_thread (arg=0x2c37910) at /bzr/5.6_dbg/Percona-Server-5.6.14-rel62.0/storage/perfschema/pfs.cc:1858
#22 0x000000362fa07851 in start_thread () from /lib64/libpthread.so.0
#23 0x000000362f2e894d in clone () from /lib64/libc.so.6

Query (7f3814004ed0): ALTER TABLE query030879 . `t1` DROP COLUMN `pk`
Connection ID (thread ID): 132
Status: NOT_KILLED

[Roel Van de Paar (roel11)]

Server: 508 <email address hidden>
RQG: 940 <email address hidden>

[Roel Van de Paar (roel11)]

See bug 1204880

[Laurynas Biveinis (laurynas-biveinis)]

Unable to tell the cause from the core dump. Were there I_S.TEMP_TABLES queries in this run?

[Roel Van de Paar (roel11)]

Possibly. The yy grammar may have selected one. Does the backtrace from all threads show anything in this area/anything of interest?

[Laurynas Biveinis (laurynas-biveinis)]

Nope. Should we revisit this after I_S.TEMP_TABLES fixes then?

[Roel Van de Paar (roel11)]

If there is no clear correlation, let's assume it is not I_S.TEMP_TABLES related?

Adding another occurrence which may help. This time there is the following in the error log:

2013-12-12 12:18:34 1118 [Note] /ssd/Percona-Server-5.6.14-rel62.0-508-debug.Linux.x86_64/bin/mysqld: ready for connections.
Version: '5.6.14-rel62.0-debug-log' socket: '/ssd//125715/current1_2/tmp/master.sock' port: 13020 Percona Server with XtraDB (GPL), Release rel62.0, Revision
 508-debug
InnoDB: Error: trying to do an operation on a dropped tablespace 35
InnoDB: Error: trying to do an operation on a dropped tablespace 35
[...more of the same...]
InnoDB: Error: trying to do an operation on a dropped tablespace 35
InnoDB: Error: trying to do an operation on a dropped tablespace 35
mysqld: /bzr/5.6_dbg/Percona-Server-5.6.14-rel62.0/sql/handler.cc:2468: THD* handler::ha_thd() const: Assertion `!table || !table->in_use || table->in_use == _current_thd()' failed.
09:22:28 UTC - mysqld got signal 6 ;

And, the query is interesting also:

Query (7f4088004ed0): OPTIMIZE TABLE `table500_innodb_compressed`

[Roel Van de Paar (roel11)]

Core upload failing, retrying few times

[Roel Van de Paar (roel11)]

Still seen on Percona-Server-5.6.19-rel67.0-619

[Laurynas Biveinis (laurynas-biveinis)]

Analyzed core dump and source code to no avail. More data is needed to proceed.

How repeatable is this? I guess not that much?

Is this seen with threadpool only or with regular connection handling too?

[Roel Van de Paar (roel11)]

Another occurence. Again with --thread_handling=pool-of-threads. Looks to be tp specific. Not seen often. Uploading files.

[Laurynas Biveinis (laurynas-biveinis)]

Likely to be fixed in the last batch of I_S.GLOBAL_TEMP_TABLES fixes.

[Launchpad Janitor (janitor)]

[Expired for Percona Server 5.6 because there has been no activity for 60 days.]

[Launchpad Janitor (janitor)]

[Expired for Percona Server 5.5 because there has been no activity for 60 days.]

[Launchpad Janitor (janitor)]

[Expired for Percona Server 5.7 because there has been no activity for 60 days.]

[Shahriyar Rzayev (rzayev-sehriyar)]

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