| Bug #64512 | error 56 upon abnormal disconnect when temporary tables exist, crash | ||
|---|---|---|---|
| Submitted: | 1 Mar 2012 10:48 | Modified: | 16 May 2012 18:23 |
| Reporter: | Russell Levy | Email Updates: | |
| Status: | No Feedback | Impact on me: | |
| Category: | MySQL Server: InnoDB storage engine | Severity: | S1 (Critical) |
| Version: | 5.6.4 | OS: | Linux |
| Assigned to: | CPU Architecture: | Any | |
| Tags: | crash, tables, temporary | ||
[1 Mar 2012 10:48]
Russell Levy
[1 Mar 2012 11:31]
Russell Levy
Hi, I just noticed that it happened again. It may be that this happens on connections that time out (which is why it was hard for me to reproduce it).
[1 Mar 2012 11:31]
Russell Levy
Changed severity to critical, as it crashes the server.
[6 Mar 2012 16:49]
Sveta Smirnova
Thank you for the report. I can not repeat described behavior. Please describe how you create temporary tables and what you do with them?
[7 Mar 2012 21:06]
Russell Levy
Unfortunately I am not sure which temporary table crashed the system. Our code creates temporary tables in seven separate areas, and since the problem only manifested on disconnect, it was hard to figure it out. Is it possible to find it in the binary logs? I have had to downgrade back to 5.5 because of this issue and I can't test further.
[9 Mar 2012 17:14]
Sveta Smirnova
Thank you for the feedback. > Is it possible to find it in the binary logs? Probably. At least we can try. If you attach binary logs, please, attach full error log also: maybe we will find something interesting in it too.
[10 Mar 2012 21:16]
Russell Levy
Hi, For security reasons I cannot attach a raw binary log (it contains other client data). When I tried to pull it out for this one database with mysqlbinlog --database=skyview --start-datetime='2012-2-22 0:00:00' --stop-datetime='2012-3-1 3:04:00' mysql-bin.0000[678]* --base64-output=never -v It didn't seem to have the data that was put in the database during that time. Am I doing something wrong?
[13 Mar 2012 19:17]
Sveta Smirnova
Thank you for the feedback. You specified option "--base64-output=never". This means no ROW event would be displayed. Please re-run without this option.
[13 Mar 2012 20:30]
Russell Levy
Hi, I have attached the binlog, starting with the first entry for thread 155 (the one specified in the log file) and ending with the crash. The first comment has a paste of the error log. If you need more (crash recovery information), I can put that in as well
[28 Mar 2012 23:22]
Leo Kwan
Error can be repeat by the following steps. mysql> use PlayGround; Database changed mysql> create temporary table Tmp (ID int) engine innodb; Query OK, 0 rows affected (0.00 sec) mysql> insert into Tmp values (1); Query OK, 1 row affected (0.00 sec) mysql> insert into Tmp values (2); Query OK, 1 row affected (0.00 sec) mysql> insert into Tmp values (3); Query OK, 1 row affected (0.01 sec) mysql> insert into Tmp values (4); Query OK, 1 row affected (0.00 sec) mysql> insert into Tmp values (5); Query OK, 1 row affected (0.00 sec) mysql> select * from Tmp; +------+ | ID | +------+ | 1 | | 2 | | 3 | | 4 | | 5 | +------+ 5 rows in set (0.00 sec) Then open another ssh session, and kill the mysql client kill -9 23725 Server will crash with the following entry in the error log. 120328 19:14:06 [Warning] Aborted connection 21 to db: 'PlayGround' user: 'leo' host: 'localhost' (Got an error reading communication packets) 120328 19:14:06InnoDB: unknown error code 56 while dropping table:120328 19:14:06 [Warning] Invalid (old?) table or database name '#sql5c35_15_0' `tmp`.<result 2 when explaining filename '#sql5c35_15_0'>. 120328 19:14:06 InnoDB: Assertion failure in thread 139983234729728 in file trx0trx.cc line 714 InnoDB: Failing assertion: ib_vector_is_empty(trx->lock.table_locks) 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.6/en/forcing-innodb-recovery.html InnoDB: about forcing recovery. 120328 19:14:06 - 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=524288 read_buffer_size=524288 max_used_connections=13 max_threads=2000 thread_count=12 connection_count=11 It is possible that mysqld could use up to key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 2072605 K bytes of memory Hope that's ok; if not, decrease some variables in the equation. Thread pointer: 0x88916b0 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 = 0x7f5062fafe50 thread_stack 0x40000 /usr/local/mysql/bin/mysqld(my_print_stacktrace+0x39)[0x860379] /usr/local/mysql/bin/mysqld(handle_segfault+0x3c7)[0x559097] /lib/x86_64-linux-gnu/libpthread.so.0(+0x10060)[0x7f519199a060] /lib/x86_64-linux-gnu/libc.so.6(gsignal+0x35)[0x7f51906373a5] /lib/x86_64-linux-gnu/libc.so.6(abort+0x17b)[0x7f519063ab0b] /usr/local/mysql/bin/mysqld[0x96917d] /usr/local/mysql/bin/mysqld[0x96a87c] /usr/local/mysql/bin/mysqld[0x930d1e] /usr/local/mysql/bin/mysqld[0x8c4bd2] /usr/local/mysql/bin/mysqld(_Z18rm_temporary_tableP10handlertonPc+0xe4)[0x653b14] /usr/local/mysql/bin/mysqld(_Z15close_temporaryP5TABLEbb+0xaa)[0x65472a] /usr/local/mysql/bin/mysqld(_Z22close_temporary_tablesP3THD+0x5fc)[0x656fac] /usr/local/mysql/bin/mysqld(_ZN3THD7cleanupEv+0x88)[0x66d8f8] /usr/local/mysql/bin/mysqld(_Z10unlink_thdP3THD+0x20)[0x55be10] /usr/local/mysql/bin/mysqld(_Z29one_thread_per_connection_endP3THDb+0x23)[0x55bec3] /usr/local/mysql/bin/mysqld(_Z24do_handle_one_connectionP3THD+0x127)[0x671a87] /usr/local/mysql/bin/mysqld(handle_one_connection+0x45)[0x671b55] /lib/x86_64-linux-gnu/libpthread.so.0(+0x7efc)[0x7f5191991efc] /lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f51906e459d] Trying to get some variables. Some pointers may be invalid and cause the dump to abort. Query ((nil)): is an invalid pointer Connection ID (thread ID): 21 Status: KILL_CONNECTION The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains information that should help you find out what is causing the crash. 120328 19:14:06 mysqld_safe Number of processes running now: 0 120328 19:14:06 mysqld_safe mysqld restarted 120328 19:14:06 [Note] Plugin 'FEDERATED' is disabled. 120328 19:14:06 InnoDB: The InnoDB memory heap is disabled 120328 19:14:06 InnoDB: Mutexes and rw_locks use GCC atomic builtins 120328 19:14:06 InnoDB: Compressed tables use zlib 1.2.3 120328 19:14:06 InnoDB: Using Linux native AIO 120328 19:14:06 InnoDB: CPU supports crc32 instructions 120328 19:14:06 InnoDB: Initializing buffer pool, size = 4.0G 120328 19:14:06 InnoDB: Completed initialization of buffer pool 120328 19:14:06 InnoDB: highest supported file format is Barracuda. InnoDB: The log sequence number in ibdata files does not match InnoDB: the log sequence number in the ib_logfiles! 120328 19:14:06 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: Last MySQL binlog file position 0 10629, file name /mysqlc/mysqld_data/log/DB12-bin.000053 InnoDB: Error: trying to load index GEN_CLUST_INDEX for table tmp/#sql16f3_4d67_1c InnoDB: but the index tree has been freed! InnoDB: Error: trying to load index GEN_CLUST_INDEX for table tmp/#sql53d8_15c6_2a InnoDB: but the index tree has been freed! InnoDB: We removed now the InnoDB internal data dictionary entry InnoDB: of table 120328 19:14:07 [Warning] Invalid (old?) table or database name '#sql5c35_15_0' "tmp".<result 2 when explaining filename '#sql5c35_15_0'>. 120328 19:14:07 InnoDB: 128 rollback segment(s) are active. 120328 19:14:07 InnoDB: Waiting for the background threads to start 120328 19:14:08 InnoDB: 1.2.4 started; log sequence number 43058008080 120328 19:14:08 [Note] Recovering after a crash using /mysqlc/mysqld_data/log/DB12-bin 120328 19:14:08 [Note] Starting crash recovery... 120328 19:14:08 [Note] Crash recovery finished. 120328 19:14:08 [ERROR] /usr/local/mysql/bin/mysqld: Table './mysql/event' is marked as crashed and should be repaired 120328 19:14:08 [Warning] Checking table: './mysql/event' 120328 19:14:08 [ERROR] 1 client is using or hasn't closed the table properly 120328 19:14:08 [Note] Event Scheduler: Loaded 3 events 120328 19:14:08 [Note] /usr/local/mysql/bin/mysqld: ready for connections. Version: '5.6.4-m7-log' socket: '/tmp/mysql.sock' port: 3306 MySQL Community Server (GPL) 120328 19:14:08 [Note] Event Scheduler: scheduler thread started with id 1
[16 Apr 2012 18:23]
Sveta Smirnova
Leo, thank you for the test case. I can not repeat described behavior with version 5.6.5. Please try with this current version and if problem still exists provide your configuration file.
[17 May 2012 1:00]
Bugs System
No feedback was provided for this bug for over a month, so it is being suspended automatically. If you are able to provide the information that was originally requested, please do so and change the status of the bug back to "Open".
