InnoDB: Failing assertion: node->n_pending == 0 in file fil0fil.c line 2415 | abort in fil_delete_tablespace

[IT Operations]

We encountered a crash of percona server under high load. This is after a week or 2 since we updated percona. Versions used:
Percona-Server-shared-55-5.5.29-rel29.4.401.rhel6.x86_64
Percona-Server-server-55-5.5.29-rel29.4.401.rhel6.x86_64
percona-toolkit-2.1.8-1.noarch
Percona-Server-client-55-5.5.29-rel29.4.401.rhel6.x86_64
percona-xtrabackup-2.0.5-499.rhel6.x86_64
Percona-Server-shared-compat-5.5.29-rel29.4.401.rhel6.x86_64
Percona-Server-test-55-5.5.29-rel29.4.401.rhel6.x86_64

The error log captured this:

130214 16:08:15 [Warning] IP address '10.208.39.190' could not be resolved: Name or service not known
130218 2:23:36 InnoDB: Assertion failure in thread 140442299004672 in file fil0fil.c line 2415
InnoDB: Failing assertion: node->n_pending == 0
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.5/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
01:23:36 UTC - 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.
Please help us make Percona Server better by reporting any
bugs at http://bugs.percona.com/

key_buffer_size=4294967296
read_buffer_size=2097152
max_used_connections=207
max_threads=1500
thread_count=118
connection_count=118
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 13428690 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x12d29020
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 = 7fbb4557ee58 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x35)[0x7ac7e5]
/usr/sbin/mysqld(handle_fatal_signal+0x4a4)[0x688084]
/lib64/libpthread.so.0(+0xf500)[0x7fbebb5c1500]
/lib64/libc.so.6(gsignal+0x35)[0x7fbeba7898a5]
/lib64/libc.so.6(abort+0x175)[0x7fbeba78b085]
/usr/sbin/mysqld[0x8ecdd9]
/usr/sbin/mysqld[0x8443f8]
/usr/sbin/mysqld[0x82ad39]
/usr/sbin/mysqld(_Z15ha_delete_tableP3THDP10handlertonPKcS4_S4_b+0xae)[0x68d98e]
/usr/sbin/mysqld(_Z14quick_rm_tableP10handlertonPKcS2_j+0x135)[0x5ec6e5]
/usr/sbin/mysqld(_Z17mysql_alter_tableP3THDPcS1_P24st_ha_create_informationP10TABLE_LISTP10Alter_infojP8st_orderb+0x255c)[0x5eec6c]
/usr/sbin/mysqld(_Z20mysql_recreate_tableP3THDP10TABLE_LIST+0x166)[0x5efea6]
/usr/sbin/mysqld[0x636813]
/usr/sbin/mysqld(_ZN24Optimize_table_statement7executeEP3THD+0xe0)[0x637340]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x1310)[0x58ab90]
/usr/sbin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x333)[0x58e483]
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x15cd)[0x58fafd]
/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0xd7)[0x62a397]
/usr/sbin/mysqld(handle_one_connection+0x51)[0x62a4d1]
/lib64/libpthread.so.0(+0x7851)[0x7fbebb5b9851]
/lib64/libc.so.6(clone+0x6d)[0x7fbeba83f11d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7fb8145aa830): is an invalid pointer
Connection ID (thread ID): 3239136
Status: NOT_KILLED

You may download the Percona Server operations manual by visiting
http://www.percona.com/software/percona-server/. You may find information
in the manual which will help you identify the cause of the crash.
130218 02:23:37 mysqld_safe Number of processes running now: 0
130218 02:23:37 mysqld_safe mysqld restarted
130218 2:23:37 [Warning] The syntax '--log-slow-queries' is deprecated and will be removed in a future release. Please use '--slow-query-log'/'--slow-query-log-file' instead.
130218 2:23:37 [Note] Plugin 'FEDERATED' is disabled.
130218 2:23:37 InnoDB: The InnoDB memory heap is disabled
130218 2:23:37 InnoDB: Mutexes and rw_locks use GCC atomic builtins
130218 2:23:37 InnoDB: Compressed tables use zlib 1.2.3
130218 2:23:37 InnoDB: Using Linux native AIO
130218 2:23:37 InnoDB: Initializing buffer pool, size = 9.0G
InnoDB: HugeTLB: Warning: Failed to allocate 9927917568 bytes. errno 1
InnoDB HugeTLB: Warning: Using conventional memory pool
130218 2:23:38 InnoDB: Completed initialization of buffer pool
130218 2:23:38 InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 12042613609937
130218 2:23:38 InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
InnoDB: Doing recovery: scanned up to log sequence number 12042618852352
InnoDB: Doing recovery: scanned up to log sequence number 12042624095232
InnoDB: Doing recovery: scanned up to log sequence number 12042629338112
InnoDB: Doing recovery: scanned up to log sequence number 12042634580992
InnoDB: Doing recovery: scanned up to log sequence number 12042639823872
InnoDB: Doing recovery: scanned up to log sequence number 12042645066752
InnoDB: Doing recovery: scanned up to log sequence number 12042650309632
InnoDB: Doing recovery: scanned up to log sequence number 12042655552512
InnoDB: Doing recovery: scanned up to log sequence number 12042660795392
InnoDB: Doing recovery: scanned up to log sequence number 12042666038272
InnoDB: Doing recovery: scanned up to log sequence number 12042671281152
InnoDB: Doing recovery: scanned up to log sequence number 12042676524032
InnoDB: Doing recovery: scanned up to log sequence number 12042681766912
InnoDB: Doing recovery: scanned up to log sequence number 12042687009792
InnoDB: Doing recovery: scanned up to log sequence number 12042692252672
InnoDB: Doing recovery: scanned up to log sequence number 12042697495552
InnoDB: Doing recovery: scanned up to log sequence number 12042702738432
InnoDB: Doing recovery: scanned up to log sequence number 12042707981312
InnoDB: Doing recovery: scanned up to log sequence number 12042713224192
InnoDB: Doing recovery: scanned up to log sequence number 12042718467072
InnoDB: Doing recovery: scanned up to log sequence number 12042723709952
InnoDB: Doing recovery: scanned up to log sequence number 12042728952832
InnoDB: Doing recovery: scanned up to log sequence number 12042734195712
InnoDB: Doing recovery: scanned up to log sequence number 12042739438592
InnoDB: Doing recovery: scanned up to log sequence number 12042744681472
InnoDB: Doing recovery: scanned up to log sequence number 12042749924352
InnoDB: Doing recovery: scanned up to log sequence number 12042755167232
InnoDB: Doing recovery: scanned up to log sequence number 12042760410112
InnoDB: Doing recovery: scanned up to log sequence number 12042765652992
InnoDB: Doing recovery: scanned up to log sequence number 12042770895872
InnoDB: Doing recovery: scanned up to log sequence number 12042776138752
InnoDB: Doing recovery: scanned up to log sequence number 12042781381632
InnoDB: Doing recovery: scanned up to log sequence number 12042786624512
InnoDB: Doing recovery: scanned up to log sequence number 12042791867392
InnoDB: Doing recovery: scanned up to log sequence number 12042797110272
InnoDB: Doing recovery: scanned up to log sequence number 12042802353152
InnoDB: Doing recovery: scanned up to log sequence number 12042807596032
InnoDB: Doing recovery: scanned up to log sequence number 12042812838912
InnoDB: Doing recovery: scanned up to log sequence number 12042818081792
InnoDB: Doing recovery: scanned up to log sequence number 12042823324672
InnoDB: Doing recovery: scanned up to log sequence number 12042828567552
InnoDB: Doing recovery: scanned up to log sequence number 12042833810432
InnoDB: Doing recovery: scanned up to log sequence number 12042839053312
InnoDB: Doing recovery: scanned up to log sequence number 12042844296192
InnoDB: Doing recovery: scanned up to log sequence number 12042849539072
InnoDB: Doing recovery: scanned up to log sequence number 12042854781952
InnoDB: Doing recovery: scanned up to log sequence number 12042860024832
InnoDB: Doing recovery: scanned up to log sequence number 12042865267712
InnoDB: Doing recovery: scanned up to log sequence number 12042870510592
InnoDB: Doing recovery: scanned up to log sequence number 12042875753472
InnoDB: Doing recovery: scanned up to log sequence number 12042880996352
InnoDB: Doing recovery: scanned up to log sequence number 12042886239232
InnoDB: Doing recovery: scanned up to log sequence number 12042891482112
InnoDB: Doing recovery: scanned up to log sequence number 12042896724992
InnoDB: Doing recovery: scanned up to log sequence number 12042901967872
InnoDB: Doing recovery: scanned up to log sequence number 12042907210752
InnoDB: Doing recovery: scanned up to log sequence number 12042912453632
InnoDB: Doing recovery: scanned up to log sequence number 12042917696512
InnoDB: Doing recovery: scanned up to log sequence number 12042922939392
InnoDB: Doing recovery: scanned up to log sequence number 12042928182272
InnoDB: Doing recovery: scanned up to log sequence number 12042933425152
InnoDB: Doing recovery: scanned up to log sequence number 12042938668032
InnoDB: Doing recovery: scanned up to log sequence number 12042943910912
InnoDB: Doing recovery: scanned up to log sequence number 12042949153792
InnoDB: Doing recovery: scanned up to log sequence number 12042954396672
InnoDB: Doing recovery: scanned up to log sequence number 12042959639552
InnoDB: Doing recovery: scanned up to log sequence number 12042964882432
InnoDB: Doing recovery: scanned up to log sequence number 12042970125312
InnoDB: Doing recovery: scanned up to log sequence number 12042975368192
InnoDB: Doing recovery: scanned up to log sequence number 12042980611072
InnoDB: Doing recovery: scanned up to log sequence number 12042985853952
InnoDB: Doing recovery: scanned up to log sequence number 12042991096832
InnoDB: Doing recovery: scanned up to log sequence number 12042996339712
InnoDB: Doing recovery: scanned up to log sequence number 12043001582592
InnoDB: Doing recovery: scanned up to log sequence number 12043006825472
InnoDB: Doing recovery: scanned up to log sequence number 12043012068352
InnoDB: Doing recovery: scanned up to log sequence number 12043017311232
InnoDB: Doing recovery: scanned up to log sequence number 12043022554112
InnoDB: Doing recovery: scanned up to log sequence number 12043027796992
InnoDB: Doing recovery: scanned up to log sequence number 12043033039872
InnoDB: Doing recovery: scanned up to log sequence number 12043038282752
InnoDB: Doing recovery: scanned up to log sequence number 12043043525632
InnoDB: Doing recovery: scanned up to log sequence number 12043048768512
InnoDB: Doing recovery: scanned up to log sequence number 12043054011392
InnoDB: Doing recovery: scanned up to log sequence number 12043059254272
InnoDB: Doing recovery: scanned up to log sequence number 12043064497152
InnoDB: Doing recovery: scanned up to log sequence number 12043069740032
InnoDB: Doing recovery: scanned up to log sequence number 12043074982912
InnoDB: Doing recovery: scanned up to log sequence number 12043080225792
InnoDB: Doing recovery: scanned up to log sequence number 12043085468672
InnoDB: Doing recovery: scanned up to log sequence number 12043090711552
InnoDB: Doing recovery: scanned up to log sequence number 12043095954432
InnoDB: Doing recovery: scanned up to log sequence number 12043101197312
InnoDB: Doing recovery: scanned up to log sequence number 12043106440192
InnoDB: Doing recovery: scanned up to log sequence number 12043111683072
InnoDB: Doing recovery: scanned up to log sequence number 12043114035027
InnoDB: in total 11 row operations to undo
InnoDB: Trx id counter is A01D1A00
130218 2:24:02 InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
130218 2:24:04 InnoDB: Rolling back trx with id A01D18EE, 11 rows to undo
InnoDB: Dropping table with id 39791 in recovery if it exists
InnoDB: Error: trying to load index PRIMARY for table lcg_frFR/#sql2-2e46-316ce0
InnoDB: but the index tree has been freed!

InnoDB: Rolling back of trx id A01D18EE completed
130218 2:24:04 InnoDB: Waiting for the background threads to start
130218 2:24:05 Percona XtraDB (http://www.percona.com) 1.1.8-rel29.4 started; log sequence number 12043114035027
130218 2:24:05 [Note] Server hostname (bind-address): '0.0.0.0'; port: 3306
130218 2:24:05 [Note] - '0.0.0.0' resolves to '0.0.0.0';
130218 2:24:05 [Note] Server socket created on IP: '0.0.0.0'.
130218 2:24:05 [Note] Event Scheduler: Loaded 0 events
130218 2:24:05 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.5.29-29.4-log' socket: '/tmp/mysql.sock' port: 3306 Percona Server (GPL), Release rel29.4, Revision 401
InnoDB: Error: trying to load index PRIMARY for table lcg_frFR/#sql2-2e46-316ce0
InnoDB: but the index tree has been freed!
InnoDB: Error: trying to load index PRIMARY for table lcg_frFR/#sql2-2e46-316ce0
InnoDB: but the index tree has been freed!
InnoDB: Error: trying to load index PRIMARY for table lcg_frFR/#sql2-2e46-316ce0
InnoDB: but the index tree has been freed!
InnoDB: Error: trying to load index PRIMARY for table lcg_frFR/#sql2-2e46-316ce0
InnoDB: but the index tree has been freed!
InnoDB: Error: trying to load index PRIMARY for table lcg_frFR/#sql2-2e46-316ce0
InnoDB: but the index tree has been freed!
InnoDB: Error: trying to load index PRIMARY for table lcg_frFR/#sql2-2e46-316ce0
InnoDB: but the index tree has been freed!
InnoDB: Error: trying to load index PRIMARY for table lcg_frFR/#sql2-2e46-316ce0
InnoDB: but the index tree has been freed!
InnoDB: Error: trying to load index PRIMARY for table lcg_frFR/#sql2-2e46-316ce0
InnoDB: but the index tree has been freed!
<snip. this goes on for a long while>

Please let us know if we can provide any other information to assist in finding the cause for this. If it happens again we'll update this ticket.

[IT Operations (itops-box)]

Btw, dmesg and kernel message log did not show any events related to hardware problems. Hardware health seems fine.

[Valerii Kravchuk (valerii-kravchuk)]

Do you use innodb_file_per_table=1? I wonder if this is related to upstream http://bugs.mysql.com/bug.php?id=66718.

[IT Operations (itops-box)]

Indeed we do user innodb_file_per_table

[Michael Coburn (michaelcoburn)]

Same crash here, pasted below. In this workload's case there are approximately 1k temporary InnoDB tables created per second (from Zend) so our first attempt to avoid this crash is to set @@default_storage_engine=MyISAM

130221 5:27:23 InnoDB: Assertion failure in thread 140436716721920 in file fil0fil.c line 2415
InnoDB: Failing assertion: node->n_pending == 0
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.5/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
10:27:23 UTC - 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.
Please help us make Percona Server better by reporting any
bugs at http://bugs.percona.com/

key_buffer_size=8388608
read_buffer_size=131072
max_used_connections=153
max_threads=2000
thread_count=30
connection_count=30
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 4384707 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x5078f6a0
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 = 7fb9f89d0e58 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x35)[0x7ac7e5]
/usr/sbin/mysqld(handle_fatal_signal+0x4a4)[0x688084]
/lib64/libpthread.so.0(+0xf500)[0x7fc5d616c500]
/lib64/libc.so.6(gsignal+0x35)[0x7fc5d53348a5]
/lib64/libc.so.6(abort+0x175)[0x7fc5d5336085]
/usr/sbin/mysqld[0x8ecdd9]
/usr/sbin/mysqld[0x8443f8]
/usr/sbin/mysqld[0x82ad39]
/usr/sbin/mysqld(_Z18rm_temporary_tableP10handlertonPc+0xf4)[0x54ed54]
/usr/sbin/mysqld(_Z15close_temporaryP5TABLEbb+0xba)[0x54ee6a]
/usr/sbin/mysqld(_Z21close_temporary_tableP3THDP5TABLEbb+0xf9)[0x5532e9]
/usr/sbin/mysqld(_Z20drop_temporary_tableP3THDP10TABLE_LISTPb+0x79)[0x5533e9]
/usr/sbin/mysqld(_Z23mysql_rm_table_no_locksP3THDP10TABLE_LISTbbbb+0x242)[0x5eb842]
/usr/sbin/mysqld(_Z14mysql_rm_tableP3THDP10TABLE_LISTcc+0x15d)[0x5ec4fd]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0x127a)[0x58aafa]
/usr/sbin/mysqld(_ZN18Prepared_statement7executeEP6Stringb+0x3b9)[0x59ba89]
/usr/sbin/mysqld(_ZN18Prepared_statement12execute_loopEP6StringbPhS2_+0x7b)[0x59f36b]
/usr/sbin/mysqld(_Z19mysqld_stmt_executeP3THDPcj+0x21e)[0x59f99e]
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x1390)[0x58f8c0]
/usr/sbin/mysqld(_Z24do_handle_one_connectionP3THD+0xd7)[0x62a397]
/usr/sbin/mysqld(handle_one_connection+0x51)[0x62a4d1]
/lib64/libpthread.so.0(+0x7851)[0x7fc5d6164851]
/lib64/libc...

[Michael Coburn (michaelcoburn)]

Sorry forgot to include versions:

percona-release-0.0-1.x86_64
percona-xtrabackup-2.0.5-499.rhel6.x86_64
percona-toolkit-2.1.8-1.noarch
Percona-Server-shared-55-5.5.29-rel29.4.401.rhel6.x86_64
Percona-Server-server-55-5.5.29-rel29.4.401.rhel6.x86_64
Percona-Server-shared-compat-5.5.29-rel29.4.401.rhel6.x86_64
Percona-Server-client-55-5.5.29-rel29.4.401.rhel6.x86_64

[Laurynas Biveinis (laurynas-biveinis)]

IT Operations, Michael, and everybody else who might encounter this -

please see if you can have gdb installed on the server in order to provide the stacktraces from all the server threads at the crash time, not only from the crashing one.

[Roel Van de Paar (roel11)]

Bug confirmed by QA automated RQG monitoring.

========================= Error log:
InnoDB: Assertion failure in thread 494348032 in file fil0fil.c line 2415
InnoDB: Failing assertion: node->n_pending == 0

========================= gdb :
Thread 1 (LWP 19186):
+bt
#0 0x00007f8198c4e69c in pthread_kill () from /lib64/libpthread.so.0
#1 0x000000000069ad26 in handle_fatal_signal (sig=6) at /home/jenkins/workspace/percona-server-5.5-nigthly-binaries/label_exp/centos5-64/Percona-Server-5.5.28-rel29.3/sql/signal_handler.cc:250
#2 <signal handler called>
#3 0x00007f8197e198a5 in raise () from /lib64/libc.so.6
#4 0x00007f8197e1b085 in abort () from /lib64/libc.so.6
#5 0x00000000008c02da in fil_delete_tablespace (id=21441, evict_all=0) at /home/jenkins/workspace/percona-server-5.5-nigthly-binaries/label_exp/centos5-64/Percona-Server-5.5.28-rel29.3/storage/innobase/fil/fil0fil.c:2415
#6 0x0000000000811f96 in row_drop_table_for_mysql (name=<optimized out>, trx=0x7f8130065788, drop_db=<optimized out>) at /home/jenkins/workspace/percona-server-5.5-nigthly-binaries/label_exp/centos5-64/Percona-Server-5.5.28-rel29.3/storage/innobase/row/row0mysql.c:3577
#7 0x00000000007f3461 in ha_innobase::delete_table (this=<optimized out>, name=0x7f8194204fe0 "./query118598/#sql2-4802-8f") at /home/jenkins/workspace/percona-server-5.5-nigthly-binaries/label_exp/centos5-64/Percona-Server-5.5.28-rel29.3/storage/innobase/handler/ha_innodb.cc:8450
#8 0x000000000069ff81 in ha_delete_table (thd=0x237d040, table_type=0x1b4c1d0, path=0x4af2 <Address 0x4af2 out of bounds>, db=0x7f8130015cc0 "query118598", alias=0x7f8194206ea0 "#sql2-4802-8f", generate_warning=false) at /home/jenkins/workspace/percona-server-5.5-nigthly-binaries/label_exp/centos5-64/Percona-Server-5.5.28-rel29.3/sql/handler.cc:2211
#9 0x00000000005e2c3d in quick_rm_table (base=0x1b4c1d0, db=0x7f8130015cc0 "query118598", table_name=0x7f8194206ea0 "#sql2-4802-8f", flags=0) at /home/jenkins/workspace/percona-server-5.5-nigthly-binaries/label_exp/centos5-64/Percona-Server-5.5.28-rel29.3/sql/sql_table.cc:2416
#10 0x00000000005e5430 in mysql_alter_table (thd=0x237d040, new_db=0x7f8130015cc0 "query118598", new_name=0x7f8130015cd8 "t14", create_info=0x7f81942074e0, table_list=0x7f8130015d18, alter_info=0x7f81942075c0, order_num=0, order=0x0, ignore=false) at /home/jenkins/workspace/percona-server-5.5-nigthly-binaries/label_exp/centos5-64/Percona-Server-5.5.28-rel29.3/sql/sql_table.cc:7004
#11 0x00000000007c2000 in Alter_table_statement::execute (this=<optimized out>, thd=0x237d040) at /home/jenkins/workspace/percona-server-5.5-nigthly-binaries/label_exp/centos5-64/Percona-Server-5.5.28-rel29.3/sql/sql_alter.cc:106
#12 0x000000000057feb6 in mysql_execute_command (thd=0x237d040) at /home/jenkins/workspace/percona-server-5.5-nigthly-binaries/label_exp/centos5-64/Percona-Server-5.5.28-rel29.3/sql/sql_parse.cc:4631
#13 0x0000000000584413 in mysql_parse (thd=0x237d040, rawbuf=<optimized out>, length=<optimized out>, parser_state=0x7f8194208b80) at /home/jenkins/workspace/percona-server-5.5-nigthly-binaries/label_exp/centos5-64/Percona-Server-5.5.28-rel29.3/sql/sql_parse.cc:5860
#14 0x00000000005858da in dispatch_comma...

[Roel Van de Paar (roel11)]

From error logs:

Case 1:
   Query (1746d3a0): TRUNCATE `table500_innodb_compressed_int_autoinc`
Case 2:
   Query (7f8130015be0): ALTER TABLE query118598 . `t14` DROP COLUMN `c42`

Case 1 was running Valgrind. No Valgrind stacks seen before assert happens.

[Vladimir Sverzhinsky (v-sverzhinsky)]

This bug actually makes PXC unusable starting from version 5.5.29 (see: https://bugs.launchpad.net/percona-xtradb-cluster/+bug/1134129).
Adding that project.

[Raghavendra D Prabhu (raghavendra-prabhu)]

a)There seems to be something wrong with backtrace in #8

#5 0x00000000008c02da in fil_delete_tablespace (id=484, evict_all=1) at /home/jenkins/workspace/percona-server-5.5-nigthly-binaries/label_exp/centos5-64/Percona-Server-5.5.28-rel29.3/storage/innobase/fil/fil0fil.c:2415
#6 0x00000000008c036d in fil_discard_tablespace (id=29462) at /home/jenkins/workspace/percona-server-5.5-nigthly-binaries/label_exp/centos5-64/Percona-Server-5.5.28-rel29.3/storage/innobase/fil/fil0fil.c:2500

The space id is 29462 in fil_discard_tablespace but in
fil_delete_tablespace shows 484.

b) In fil_delete_tablespace, it already checks for
node->n_pending in a loop but inside a fil_system->mutex which it
later drops before reacquiring. Is it not possible that during
this gap, node receives additional I/O? (from fil_node_prepare_for_io)

c) I also see fil_flush_file_spaces waiting on fil_system->mutex
(with purpose of FIL_TABLESPACE), can this be the pending I/O
waiting on the node? (hence blocked by fil_system->mutex acquired
again)

[Raghavendra D Prabhu (raghavendra-prabhu)]

@Vladimir and other bug reporters:

Can you share your my.cnf?

[IT Operations (itops-box)]

my.cnf as requested

[Raghavendra D Prabhu (raghavendra-prabhu)]

@IT Operations, Thanks. The primary reason I requested was to see if it is a regression with innodb_lazy_drop_table. It seems to be set to 1. However, will need to check with others as well.

The regression I suspect may be due to lp:1076215 since from the comments above it looks like it got introduced in 5.5.29 PS

[Vladimir Sverzhinsky (v-sverzhinsky)]

Find our version of my.cnf attached.
We do use innodb_lazy_drop_table=1 as can be seen in my.cnf.

[Raghavendra D Prabhu (raghavendra-prabhu)]

To collate, it looks like the crash is triggered when innodb_lazy_drop_table is 1 (all reporters in this bug have it). Furthermore, lp:1154558 also is similar to this - the server crashes over waiting for hash index ref_count to drop to 0 (and disabling lazy drop table fixes it).

Has it crashed for anyone with innodb_lazy_drop_table set to 0?

Similar issue reported here - https://mariadb.atlassian.net/browse/MDEV-4256

[Shahriyar Rzayev (rzayev-sehriyar)]

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

[Shahriyar Rzayev (rzayev-sehriyar)]

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