| Bug #61104 | InnoDB: Failing assertion: page_get_n_recs(page) > 1 | ||
|---|---|---|---|
| Submitted: | 9 May 2011 16:34 | Modified: | 15 Feb 2012 9:46 |
| Reporter: | Laurent Bigonville | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | MySQL Server: InnoDB storage engine | Severity: | S1 (Critical) |
| Version: | 5.5.13, 5.5.15, 5.5.16 | OS: | Any |
| Assigned to: | CPU Architecture: | Any | |
[9 May 2011 16:34]
Laurent Bigonville
[23 May 2011 8:37]
Laurent Bigonville
So I did a complete dump of the database (plain .sql files) and the a complete reimport and this is still occurring. I've restarted the server after the import and then reenable the replication and then it crashed again with the same error in the logs
[24 May 2011 8:39]
Laurent Bigonville
When setting innodb_force_recovery to 1 the server is crashing the same way. With innodb_force_recovery >= 2 the server never start completely I get "InnoDB: Waiting for the background threads to start" in loop in the logs and it seems that the socket is not created
[6 Jun 2011 12:50]
Laurent Bigonville
With 5.5.13, starting the server with innodb_force_recovery >= 2 is working again. To complete the informations here: I have the tables of one of my database that are on a different partition, if I start the server and the replication without that partition mounted, the server is working fine. As soon as I mount this partition (after shutting down the server and restarting it) the server is crashing. All the tables in that DB is in archive format and there is no changes to this DB through the replication. Even after unmounting this partition the server keeps crashing
[7 Jun 2011 10:44]
Laurent Bigonville
So I've dropped the databases where all tables are in archive format and restore it from a backup, the server is not crashing anymore. I'm a but puzzled that the assertion seemed to be in innodb engine, and that recreating archive table fix it...
[9 Jun 2011 12:04]
Laurent Bigonville
Alright, new update. The server crashed again today with the same error, after 2 days of running. 110609 13:26:04 InnoDB: Assertion failure in thread 139869585753872 in file ibuf0ibuf.c line 4185 InnoDB: Failing assertion: page_get_n_recs(page) > 1 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. 110609 13:26:04 - 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=33554432 read_buffer_size=8388608 max_used_connections=6 max_threads=20 thread_count=3 connection_count=3 It is possible that mysqld could use up to key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 852195 K bytes of memory Hope that's ok; if not, decrease some variables in the equation. Thread pointer: 0x0 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 = (nil) thread_stack 0x30000 /usr/sbin/mysqld(my_print_stacktrace+0x39)[0x7bf8d9] /usr/sbin/mysqld(handle_segfault+0x3c2)[0x517362] /lib64/libpthread.so.0(+0xf5d0)[0x7f3e8ff545d0] /lib64/libc.so.6(gsignal+0x35)[0x7f3e8f179945] /lib64/libc.so.6(abort+0x181)[0x7f3e8f17af21] /usr/sbin/mysqld[0x8fb855] /usr/sbin/mysqld[0x8b0058] /usr/sbin/mysqld[0x8e0a38] /usr/sbin/mysqld[0x86ce30] /lib64/libpthread.so.0(+0x75f0)[0x7f3e8ff4c5f0] /lib64/libc.so.6(clone+0x6d)[0x7f3e8f21b84d] 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. Rising the Severity to critical.
[9 Jun 2011 12:36]
Laurent Bigonville
The crash occurs after I did some alter table engine from archive to innodb engine, not too sure if it's related
[20 Jun 2011 13:23]
Laurent Bigonville
0x7ca7c9 my_print_stacktrace + 57 0x4ff7e9 handle_segfault + 889 0x7fed662505d0 _end + 1696332848 0x7fed65475945 _end + 1681805221 0x7fed65476f21 _end + 1681810817 0x90b591 ibuf_merge_or_delete_for_page + 5777 0x8b2c55 buf_page_io_complete + 1157 0x8e90c1 fil_aio_wait + 545 0x8649e0 io_handler_thread + 80 0x7fed662485f0 _end + 1696300112 0x7fed6551784d _end + 1682468525
[20 Jun 2011 13:35]
MySQL Verification Team
Could you please provide the show create table for that archive table?. Thanks.
[20 Jun 2011 13:54]
Laurent Bigonville
I've attached the schema of all the tables from that db. I cannot be sure after which alter table to innodb the database start crashing, but it did definitly after alter table archive -> innodb and then innodb -> archive
[24 Aug 2011 8:09]
Arnaud Gadal
Hi, Same error/behavior here on a 5.5.15 (upgrade from 5.1.51), server crashes and can't recover. 110822 6:41:29 InnoDB: Assertion failure in thread 1231132992 in file ibuf0ibuf.c line 4185 InnoDB: Failing assertion: page_get_n_recs(page) > 1 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. 110822 6:41:29 - 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=2147483648 read_buffer_size=1048576 max_used_connections=96 max_threads=400 thread_count=27 connection_count=27 It is possible that mysqld could use up to key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 2920905 K bytes of memory Hope that's ok; if not, decrease some variables in the equation. Thread pointer: 0x0 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 = (nil) thread_stack 0x40000 /usr/local/mysql/bin/mysqld(my_print_stacktrace+0x39)[0x798989] /usr/local/mysql/bin/mysqld(handle_segfault+0x380)[0x4fde40] /lib64/libpthread.so.0[0x396300eb10] /lib64/libc.so.6(gsignal+0x35)[0x3962830265] /lib64/libc.so.6(abort+0x110)[0x3962831d10] /usr/local/mysql/bin/mysqld[0x86f56a] /usr/local/mysql/bin/mysqld[0x825be2] /usr/local/mysql/bin/mysqld[0x833e6e] /usr/local/mysql/bin/mysqld[0x834367] /usr/local/mysql/bin/mysqld[0x8282de] /usr/local/mysql/bin/mysqld[0x8121b5] /usr/local/mysql/bin/mysqld[0x7cd457] /usr/local/mysql/bin/mysqld[0x8b2cc3] /usr/local/mysql/bin/mysqld[0x8b3351] /usr/local/mysql/bin/mysqld[0x8b3c5d] /usr/local/mysql/bin/mysqld[0x8a978d] /usr/local/mysql/bin/mysqld[0x7eb245] /usr/local/mysql/bin/mysqld[0x7df83e] /lib64/libpthread.so.0[0x396300673d] /lib64/libc.so.6(clone+0x6d)[0x39628d44bd] 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. mysqld: /export/home/pb2/build/sb_0-3619245-1310586449.63/mysql-5.5.15/mysys/my_new.cc:52: int __cxa_pure_virtual(): Assertion `! "Aborted: pure virtual method called."' failed. 110822 06:41:31 mysqld_safe Number of processes running now: 0 110822 06:41:31 mysqld_safe mysqld restarted 110822 6:41:31 [Note] Plugin 'FEDERATED' is disabled. 110822 6:41:32 InnoDB: The InnoDB memory heap is disabled 110822 6:41:32 InnoDB: Mutexes and rw_locks use GCC atomic builtins 110822 6:41:32 InnoDB: Compressed tables use zlib 1.2.3 110822 6:41:32 InnoDB: Using Linux native AIO 110822 6:41:32 InnoDB: Initializing buffer pool, size = 20.0G 110822 6:41:33 InnoDB: Completed initialization of buffer pool 110822 6:41:33 InnoDB: highest supported file format is Barracuda. InnoDB: Log scan progressed past the checkpoint lsn 9731385362631 110822 6:41:33 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 9731390605312 InnoDB: Doing recovery: scanned up to log sequence number 9731395848192 InnoDB: Doing recovery: scanned up to log sequence number 9731401091072 [...] InnoDB: Doing recovery: scanned up to log sequence number 9734059231232 InnoDB: Doing recovery: scanned up to log sequence number 9734062943366 110822 6:42:33 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 110822 6:43:03 InnoDB: Assertion failure in thread 1138682176 in file ibuf0ibuf.c line 4185 InnoDB: Failing assertion: page_get_n_recs(page) > 1 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. 110822 6:43:03 - 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=2147483648 read_buffer_size=1048576 max_used_connections=0 max_threads=400 thread_count=0 connection_count=0 It is possible that mysqld could use up to key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 2920905 K bytes of memory Hope that's ok; if not, decrease some variables in the equation. Thread pointer: 0x0 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 = (nil) thread_stack 0x40000 /usr/local/mysql/bin/mysqld(my_print_stacktrace+0x39)[0x798989] /usr/local/mysql/bin/mysqld(handle_segfault+0x380)[0x4fde40] /lib64/libpthread.so.0[0x396300eb10] /lib64/libc.so.6(gsignal+0x35)[0x3962830265] /lib64/libc.so.6(abort+0x110)[0x3962831d10] /usr/local/mysql/bin/mysqld[0x86f56a] /usr/local/mysql/bin/mysqld[0x825be2] /usr/local/mysql/bin/mysqld[0x854d08] /usr/local/mysql/bin/mysqld[0x7e2d10] /lib64/libpthread.so.0[0x396300673d] /lib64/libc.so.6(clone+0x6d)[0x39628d44bd] 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. 110822 06:43:04 mysqld_safe mysqld from pid file /data/mysql/mysql152.xxx.com.pid ended 110822 07:36:38 mysqld_safe Starting mysqld daemon with databases from /data/mysql 110822 7:36:38 [Note] Plugin 'FEDERATED' is disabled. 110822 7:36:38 InnoDB: The InnoDB memory heap is disabled 110822 7:36:38 InnoDB: Mutexes and rw_locks use GCC atomic builtins 110822 7:36:38 InnoDB: Compressed tables use zlib 1.2.3 110822 7:36:38 InnoDB: Using Linux native AIO 110822 7:36:38 InnoDB: Initializing buffer pool, size = 20.0G 110822 7:36:40 InnoDB: Completed initialization of buffer pool 110822 7:36:40 InnoDB: highest supported file format is Barracuda. InnoDB: Log scan progressed past the checkpoint lsn 9731385362631 110822 7:36:40 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 9731390605312 InnoDB: Doing recovery: scanned up to log sequence number 9731395848192 CentOS release 5.4 (Final) and package is mysql-5.5.15-linux2.6-x86_64.tar.gz Regards, Arnaud
[23 Sep 2011 6:00]
Ilkka Kerminen
We have crashed into this bug recently and we really hope Oracle fixes this bug asap, since it prevents us from using this version of Mysql in production. Ilkka
[23 Sep 2011 6:09]
Valeriy Kravchuk
See Bug #61324 also. Probably a duplicate (upgrade also happened there).
[28 Oct 2011 7:48]
Yasufumi Kinoshita
The assertion "page_get_n_recs(page) > 1" at ibuf_delete() is intended to be secured at ibuf_insert_low()
----
min_n_recs = 0;
buffered = ibuf_get_volume_buffered(&pcur, space, page_no,
op == IBUF_OP_DELETE
? &min_n_recs
: NULL, &mtr);
if (op == IBUF_OP_DELETE
&& (min_n_recs < 2
|| buf_pool_watch_occurred(space, page_no))) {
----
But the min_n_recs from ibuf_get_volume_buffered() is based on the "total" of the record number change by ibuf at the time. Not seem to be considered the order of the operations.
I mean I think all ibuf_delete() should be after all ibuf_insert_to_index_page() were end at ibuf_merge_or_delete_for_page()
[29 Oct 2011 4:20]
Yasufumi Kinoshita
I might be wrong. I continue to investigate with another viewpoint.
[2 Nov 2011 5:09]
Yasufumi Kinoshita
Though I might not be right still, I feel something strange at
ibuf_set_entry_counter()
--------
counter = ibuf_get_entry_counter_low(
rec, space, page_no);
....
if (counter < cursor->ibuf_cnt) {
/* Search ended on the wrong page. */
--------
"counter" stores the next value.
"cursor->ibuf_cnt" stores the value at calling "btr_pcur_open(ibuf->index, ibuf_entry, PAGE_CUR_LE, mode, &pcur, &mtr);"
So the if() condition should be "if (counter <= cursor->ibuf_cnt) {", I think.
[20 Nov 2011 19:05]
Oded Arbel
I have the same problem - MySQL 5.5.8 GA RHEL RPMs from mysql.com on CentOS 5.6. CPU Xeon E5620 @ 2.40GHz 4x4, 140GB memory. We've had a few crashes like that in the last couple of days, and as of now the database crashes immediately after starting. There are no clients connected, we start the database with innodb_force_recovery=2 and it starts normally. We then shut it down, remove innodb_force_recovery and start it again - and it immediately crashes with the following log: 111120 18:24:06 [Note] /usr/sbin/mysqld: ready for connections. Version: '5.5.8-log' socket: '/var/lib/mysql/mysql.sock' port: 3306 MySQL Community Server (GPL) 111120 18:24:08 InnoDB: Assertion failure in thread 1366882624 in file /export/home/pb2/build/sb_0-2629600-1291401220.79/rpm/BUILD/mysql-5.5.8/mysql-5.5.8/storage/innobase/ibuf/ib uf0ibuf.c line 4069 InnoDB: Failing assertion: page_get_n_recs(page) > 1 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.1/en/forcing-recovery.html InnoDB: about forcing recovery. 111120 18:24:08 - 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=67108864 read_buffer_size=4194304 max_used_connections=0 max_threads=2000 thread_count=0 connection_count=0 It is possible that mysqld could use up to key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 16472270 K bytes of memory Hope that's ok; if not, decrease some variables in the equation. thd: 0x0 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 = (nil) thread_stack 0x40000 /usr/sbin/mysqld(my_print_stacktrace+0x39)[0x94e6a9] /usr/sbin/mysqld(handle_segfault+0x352)[0x4fc5e2] /lib64/libpthread.so.0[0x3a81c0eb10] /lib64/libc.so.6(gsignal+0x35)[0x3a81030265] /lib64/libc.so.6(abort+0x110)[0x3a81031d10] /usr/sbin/mysqld[0x8c8bc5] /usr/sbin/mysqld[0x88171f] /usr/sbin/mysqld[0x88c06f] /usr/sbin/mysqld[0x88c3b7] /usr/sbin/mysqld[0x87be6b] /usr/sbin/mysqld[0x86918e] /usr/sbin/mysqld[0x823187] /usr/sbin/mysqld[0x90f14e] /usr/sbin/mysqld[0x90fa50] /usr/sbin/mysqld[0x90501c] /usr/sbin/mysqld[0x840657] /usr/sbin/mysqld[0x834c71] /lib64/libpthread.so.0[0x3a81c0673d] /lib64/libc.so.6(clone+0x6d)[0x3a810d44bd] 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. As you can see from the logs, this happens 2 seconds after the server inits, with no clients connected at all. This is the main production server with more then 1TB of data and currently its unusable. any help will be appreciated.
[21 Nov 2011 12:52]
zohar aharoni
Don't know if it will help but we ran into this problem. It took us time but finally we managed to get over it - We started mysql in innodb_recovery_mode=2 we ran extended mysqlcheck on all databases and we saw that in some point the connection is dying. We ran it several more times and the connection kept on dying in the same table... We did mysqldump to this table and then we dropped it. After we dropped it we started the DB with innodb_recovery_mode=0 and the db started successfully. Than we imported the table that we dropped earlier and it worked, now the DB is not crashing...
[21 Nov 2011 12:53]
Marko Mäkelä
Yasufumi, thank you for your comment. Delete buffering, which was introduced in MySQL 5.5, differs from insert buffering by the fact that inserts can be buffered and merged in an arbitrary order, but a stream of insert,delete_mark,purge must preserve the order. To preserve the order, we added a counter field to the change buffer record. To get the old behaviour, you can do SET GLOBAL innodb_change_buffering=inserts; It seems that there could be a bug in the buffering of purge operations. To allow the buffering of insert and delete-mark operations but prevent purge, you can do SET GLOBAL innodb_change_buffering=changes; The idea of the cursor->ibuf_cnt is to record the value of the counter field from the node pointer record that points to the leaf page. This was tested for in ibuf_set_entry_counter(): if (counter < cursor->ibuf_cnt) Some weeks ago, it turned out that this code path is insecure. It is invoked when it is not known whether there are preceding change buffer records for the page. The problem is that the buf_page_get() call in ibuf_set_entry_counter() violates the latching order, because the calling thread is already holding a change buffer bitmap page latch. This could theoretically cause a deadlock. We have only seen UNIV_SYNC_DEBUG assertion failures for this. It is possible that this bug was accidentally fixed by the fix of the UNIV_SYNC_DEBUG assertion failure. We would simply refuse to buffer the operation if we cannot determine the counter value without looking at the preceding page. This fix should be included in 5.5.18.
[22 Nov 2011 10:37]
Marko Mäkelä
I analyzed a core dump from a support customer where this assertion fails. Everything in the insert buffer page looks mostly good to me. The entries for the page (which would be made empty by the result of merging the IBUF_OP_DELETE (purge) operation) were in the middle of the page, preceded by several entries for other pages and followed by one entry for another page.
In ibuf_merge_or_delete_for_page(), we have mops={0,0,1}, meaning that one purge (IBUF_OP_DELETE) operation was successfully merged during the invocation. The change buffer page contains these entries for the user secondary index leaf page:
2622 (2df,0,c08a,0012,IBUF_OP_DELETE,1) [merged and deleted]
27a0 (2df,0,c08a,0013,IBUF_OP_DELETE,1) [assertion failure: empty page]
291e (2df,0,c08a,0014,IBUF_OP_INSERT,1)
2a9c (2df,0,c08a,0015,IBUF_OP_INSERT,1)
2c1a (2df,0,c08a,0016,IBUF_OP_DELETE,1)
2d98 (2df,0,c08a,0017,IBUF_OP_DELETE,1)
It is a little strange that the page did contain other entries for the same page. They all were deleted, but apparently on a previous call, given that mops[] was {0,0,1}. But then, why did the op_counter not start from 0000? These deleted entries were as follows:
202a (2df,0,c08a,000e,IBUF_OP_DELETE_MARK,1)
21a8 (2df,0,c08a,000f,IBUF_OP_DELETE_MARK,1)
2326 (2df,0,c08a,0010,IBUF_OP_DELETE,1)
24a4 (2df,0,c08a,0011,IBUF_OP_DELETE,1)
2622 (2df,0,c08a,0012,IBUF_OP_DELETE,1) [merged and deleted on this call]
The entire contents of the PAGE_FREE list was just this: 2622,24a4,2326,21a8,202a,0000.
I am looking forward to a repeatable test case that triggers these messages in the error log. These messages were present in the support customer's error log:
InnoDB: unable to find a record to delete-mark
Because purge buffering aims to prevent empty pages by counting previously buffered records for the page, this assertion will fail if the user index entries corresponding to buffered IBUF_OP_DELETE_MARK records did not exist in the first place.
[22 Nov 2011 11:01]
Marko Mäkelä
The mystery in the core dump was solved. In the error log that I received, the very first assertion failure was immediately preceded by two InnoDB: unable to find a record to delete-mark messages. What probably happened was that these entries were applied: 202a (2df,0,c08a,000e,IBUF_OP_DELETE_MARK,1) [not found, message printed] 21a8 (2df,0,c08a,000f,IBUF_OP_DELETE_MARK,1) [not found, message printed] 2326 (2df,0,c08a,0010,IBUF_OP_DELETE,1) [ok] 24a4 (2df,0,c08a,0011,IBUF_OP_DELETE,1) [ok] 2622 (2df,0,c08a,0012,IBUF_OP_DELETE,1) [ok] 27a0 (2df,0,c08a,0013,IBUF_OP_DELETE,1) [assertion failure: empty page] Because ibuf_merge_or_delete_for_page() does mtr_commit() between buffered operations, it is likely that the merging and deletion of the records 202a,21a8 was successfully covered by the redo log. On subsequent restarts, the insert buffer merge would always crash on 27a0. In the core dump that I examined, it is likely that the deletion of records 2326,24a4 was covered by the redo log, but the redo log for merging deleting 2622 was incomplete and it was dropped by the redo log application. The open question remains: How to trigger these messages: InnoDB: unable to find a record to delete-mark
[28 Nov 2011 19:29]
Marko Mäkelä
If you get hit by this bug, the assertion may fail straight after server restart, before you get a chance to run DROP INDEX or DROP TABLE to drop the offending table, whose name you would have to fish from the core dump. The only hope is to disable insert buffer merge by innodb_force_recovery, and to dump and reload the database. Alternatively, you could drop and recreate all secondary indexes, or at least those for which CHECK TABLE complains. Workaround: use innodb_change_buffering=inserts to disable delete buffering. We have not managed to repeat the problem yet, but we should soon gain access to a dataset for repeating it.
[30 Nov 2011 13:56]
Marko Mäkelä
I witnessed this assertion failure on a customer site. There were no messages on failure to find records to delete-mark. The secondary index was a NOT NULL but non-unique index on an INT column. The primary key was an INT column. Before I started applying the binlog that triggered this bug, I initiated a slow shutdown, so that I knew that the change buffer was empty. It is clear to me that a failure to find a record to delete-mark can lead to this bug. It is not yet clear how this bug can be triggered without delete-mark failures.
[13 Jan 2012 10:49]
Simon Mudd
I've also seen this recently in 5.5.16 on a single development server and reported details to Oracle support.
[13 Jan 2012 11:03]
Valeriy Kravchuk
Bug #62581 was marked as a duplicate of this one. As a workaround, please, set innodb_change_buffering=inserts This should prevent assertion failure.
[22 Jan 2012 5:44]
MySQL Verification Team
On a side note: When starting with innodb_force_recovery, you should set innodb_purge_threads=0 to avoid a looping during startup. Bug 13616287 - STARTUP HANGS WITH "WAITING FOR THE BACKGROUND THREADS TO START"
[26 Jan 2012 12:37]
Marko Mäkelä
I pushed a patch that removes this failing assertion. It will leave the record in the page if the page would become empty. InnoDB can crash in other places due to corruption. A simple fix of the corruption might be DROP INDEX followed by CREATE INDEX. In any case, it is good to mysqldump the table first, in case the allocation data structures are corrupted within the tablespace.
[26 Jan 2012 14:49]
Marko Mäkelä
A likely cause of this corruption is Bug#58571 (a record that is expected to be delete-marked, is not).
[1 Feb 2012 2:13]
zhai weixiang
i got this bug too This bug prevents us from using mysql5.5 in a production environment is there anyone can explain why this happen , or Provide some ways to avoid this bug
[9 Feb 2012 22:49]
James Day
zhai, set innodb_change_buffering=inserts That will prevent the problem. You can remove it when we release a version with the fix. This doesn't affect every installation and people who aren't affected can leave it at the default setting.
[13 Feb 2012 21:47]
John Russell
Added to changelog for 5.5.21, 5.6.5: The MySQL server could halt with an assertion error: InnoDB: Failing assertion: page_get_n_recs(page) > 1 Subsequent restarts could fail with the same error. The error occurred during a purge operation involving the InnoDB change buffer. The workaround was to set the configuration option innodb_change_buffering=inserts.
[13 Feb 2012 21:49]
John Russell
Added to changelog for 5.5.21, 5.6.5: The MySQL server could halt with an assertion error: InnoDB: Failing assertion: page_get_n_recs(page) > 1 Subsequent restarts could fail with the same error. The error occurred during a purge operation involving the InnoDB change buffer. The workaround was to set the configuration option innodb_change_buffering=inserts.
[13 Feb 2012 21:51]
John Russell
Added to changelog for 5.5.21, 5.6.5: The MySQL server could halt with an assertion error: InnoDB: Failing assertion: page_get_n_recs(page) > 1 Subsequent restarts could fail with the same error. The error occurred during a purge operation involving the InnoDB change buffer. The workaround was to set the configuration option innodb_change_buffering=inserts.
[15 Feb 2012 9:46]
Jon Stephens
Fixed in 5.5+, documented as above. Closed.
[29 May 2012 18:28]
Mark Callaghan
Why was this closed? The commit log claims the "fix" is a workaround that avoids the assert but doesn't prevent the corruption.
>>
revno: 2875.338.20
committer: Marko Mäkelä <marko.makela@oracle.com>
branch nick: mysql-5.5
timestamp: Thu 2012-01-26 13:24:00 +0200
message:
Bug #13413535 61104: INNODB: FAILING ASSERTION: PAGE_GET_N_RECS(PAGE) > 1
This fix does not remove the underlying cause of the assertion
failure. It just works around the problem, allowing a corrupted
secondary index to be fixed by DROP INDEX and CREATE INDEX (or in the
worst case, by re-creating the table).
[2 Jul 2012 23:43]
James Day
Bug 58571 is a possible underlying cause of this bug.
[11 Jul 2012 14:21]
Bart Verwilst
Running a clean Percona 5.5.24, we're also getting the 'cosmetically enhanced' version of this bug. We dumped 3TB of data from another identical MySQL server, and reimported it through mydumper/myloader. Since then it has been catching up on 1000000 seconds from its master. I noticed this in the logs: 120709 22:26:32 [Note] Event Scheduler: Loaded 0 events 120709 22:26:32 [Note] /usr/sbin/mysqld: ready for connections. Version: '5.5.24-55-log' socket: '/var/run/mysql/mysqld.sock' port: 3306 Percona Server (GPL), Release rel26.0, Revision 256 120709 22:27:55 InnoDB: unable to purge a record InnoDB: tuple DATA TUPLE: 3 fields; 0: len 32; hex 3237333838313830383038303830383038303830383038303830383046344232; asc 2738818080808080808080808080F4B2;; 1: SQL NULL; 2: len 8; hex 80000000f90ea91f; asc ;; InnoDB: record PHYSICAL RECORD: n_fields 3; compact format; info bits 32 0: len 30; hex 323733383831383038303830383038303830383038303830383038304634; asc 2738818080808080808080808080F4; (total 32 bytes); 1: SQL NULL; 2: len 8; hex 80000000f90ea91f; asc ;; space 135 offset 14600952 (1 records, index id 333) InnoDB: Submit a detailed bug report to http://bugs.mysql.com Everything seems fine though, and i'm not seeing any other issues. However, because of maintenance i had to shut down the machine, and when my /etc/init.d/mysql stop came back rather soon, i checked the logs again, and noticed this: 120710 16:24:09 [Note] Slave SQL thread exiting, replication stopped in log 'popo-bin.000247' at position 418041479 120710 16:24:09 [Note] Slave I/O thread killed while reading event 120710 16:24:09 [Note] Slave I/O thread exiting, read up to log 'popo-bin.000379', position 97123992 120710 16:24:09 [Note] /usr/sbin/mysqld: Normal shutdown 120710 16:24:09 [Note] Event Scheduler: Purging the queue. 0 events 120710 16:24:12 InnoDB: Assertion failure in thread 140362283239168 in file ha_innodb.cc line 1289 InnoDB: Failing assertion: cset == 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. 14:24:12 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. key_buffer_size=8388608 read_buffer_size=131072 max_used_connections=4 max_threads=4096 thread_count=0 connection_count=0 It is possible that mysqld could use up to key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 8971264 K bytes of memory Hope that's ok; if not, decrease some variables in the equation. Thread pointer: 0x0 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 = 0 thread_stack 0x40000 /usr/sbin/mysqld(my_print_stacktrace+0x35)[0x7a5d85] /usr/sbin/mysqld(handle_fatal_signal+0x4a4)[0x680e04] /lib64/libpthread.so.0[0x342420f4a0] /lib64/libc.so.6(gsignal+0x35)[0x3423a32885] /lib64/libc.so.6(abort+0x175)[0x3423a34065] /usr/sbin/mysqld[0x7f3af2] /usr/sbin/mysqld[0x8d19c6] /usr/sbin/mysqld[0x8d8d2e] /usr/sbin/mysqld[0x883d7e] /usr/sbin/mysqld[0x8b41e3] /usr/sbin/mysqld[0x834c40] /lib64/libpthread.so.0[0x34242077f1] /lib64/libc.so.6(clone+0x6d)[0x3423ae5ccd] 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. 120710 16:24:13 mysqld_safe Number of processes running now: 0 120710 16:24:13 mysqld_safe mysqld restarted As seen on the last line, it restarted and started recovery. I did a shutdown after the recovery, which worked.
[11 Jul 2012 14:52]
Bart Verwilst
Index id 333 seems to be a secondary index: mysql> select IST.SCHEMA, IST.NAME, ISI.NAME from INNODB_SYS_TABLES IST INNER JOIN INNODB_SYS_INDEXES ISI ON IST.TABLE_ID = ISI.TABLE_ID and ISI.INDEX_ID=333; +--------+-----------------+---------------------+ | SCHEMA | NAME | NAME | +--------+-----------------+---------------------+ | asp | trace_poll_ejb3 | idx_customerid_mark | +--------+-----------------+---------------------+ 1 row in set (0.00 sec) While we can probably recreate it ( but it's over 300GB :( ), it's just a temporary 'fix', and it can happen at any moment again somewhere else..
[18 Sep 2012 10:15]
Marko Mäkelä
This is the probable root cause: Bug#66819 InnoDB change buffering is not entirely crash-safe
[30 Nov 2012 19:46]
James Day
If affected by this, or if you use change buffering at all, you should upgrade to 5.1.67, 5.5.29, 5.6.8 as they become available to get the fix for the likely root cause, bug 66819. If you still see this symptom after upgrading please let us know. James Day, MySQL Senior Principal Support Engineer, Oracle
[26 Mar 2013 8:26]
Bart Verwilst
Well, I'm back! Server version: 5.5.30-30.1 Percona Server (GPL), Release rel30.1, Revision 465 <snip> space 135 offset 5261543 (1 records, index id 333) InnoDB: Submit a detailed bug report to http://bugs.mysql.com 130326 4:35:26 InnoDB: unable to purge a record InnoDB: tuple DATA TUPLE: 3 fields; 0: len 32; hex 3937463638313830383038303830383038303830383038303830383043373636; asc 97F6818080808080808080808080C766;; 1: SQL NULL; 2: len 8; hex 80000001495a20c4; asc IZ ;; InnoDB: record PHYSICAL RECORD: n_fields 3; compact format; info bits 32 0: len 30; hex 393746363831383038303830383038303830383038303830383038304337; asc 97F6818080808080808080808080C7; (total 32 bytes); 1: SQL NULL; 2: len 8; hex 80000001495a20c4; asc IZ ;; space 135 offset 5157799 (1 records, index id 333) InnoDB: Submit a detailed bug report to http://bugs.mysql.com 130326 4:42:41 InnoDB: unable to purge a record InnoDB: tuple DATA TUPLE: 3 fields; 0: len 32; hex 4442373738303830383038303830383038303830383038303830383036373631; asc DB778080808080808080808080806761;; 1: SQL NULL; 2: len 8; hex 80000001495a4e93; asc IZN ;; InnoDB: record PHYSICAL RECORD: n_fields 3; compact format; info bits 32 0: len 30; hex 444237373830383038303830383038303830383038303830383038303637; asc DB7780808080808080808080808067; (total 32 bytes); 1: SQL NULL; 2: len 8; hex 80000001495a4e93; asc IZN ;; <snip> It seems to be the same index as above. I will drop and recreate it. In my general_log, i only see heaps of this: 56 Query BEGIN 56 Query COMMIT 56 Query BEGIN 56 Query COMMIT /* implicit, from Xid_log_event */ 56 Query BEGIN 56 Query COMMIT 56 Query BEGIN 56 Query COMMIT /* implicit, from Xid_log_event */ 56 Query BEGIN 56 Query COMMIT 56 Query BEGIN 56 Query COMMIT /* implicit, from Xid_log_event */ 56 Query BEGIN 56 Query COMMIT 56 Query BEGIN 56 Query COMMIT 56 Query BEGIN 56 Query COMMIT 56 Query BEGIN 56 Query COMMIT /* implicit, from Xid_log_event */ 56 Query BEGIN 56 Query COMMIT 56 Query BEGIN 56 Query COMMIT /* implicit, from Xid_log_event */ 56 Query BEGIN 56 Query COMMIT 56 Query BEGIN 56 Query COMMIT 56 Query BEGIN No actual queries. Not sure if this is related to this?
[26 Mar 2013 8:41]
Bart Verwilst
Currently doing alter table trace_poll_ejb3 drop KEY `idx_customerid_mark`, add key `idx_customerid_mark` (`customerid`,`mark`); I hope this removes the corruption from the table/index. It's 460GB though, so it will take quite some time..
[26 Mar 2013 18:55]
Bart Verwilst
Index has been rebuilt. Getting this now: space 1053 offset 20715585 (1 records, index id 3456) InnoDB: Submit a detailed bug report to http://bugs.mysql.com 130326 19:43:44 InnoDB: unable to purge a record InnoDB: tuple DATA TUPLE: 3 fields; 0: len 32; hex 3746424338313830383038303830383038303830383038303830383042373043; asc 7FBC818080808080808080808080B70C;; 1: SQL NULL; 2: len 8; hex 80000001496a7588; asc Iju ;; InnoDB: record PHYSICAL RECORD: n_fields 3; compact format; info bits 32 0: len 30; hex 374642433831383038303830383038303830383038303830383038304237; asc 7FBC818080808080808080808080B7; (total 32 bytes); 1: SQL NULL; 2: len 8; hex 80000001496a7588; asc Iju ;; space 1053 offset 20700929 (1 records, index id 3456) InnoDB: Submit a detailed bug report to http://bugs.mysql.com 130326 19:44:57 InnoDB: unable to purge a record InnoDB: tuple DATA TUPLE: 3 fields; 0: len 32; hex 3734304238313830383038303830383038303830383038303830383044363641; asc 740B818080808080808080808080D66A;; 1: SQL NULL; 2: len 8; hex 80000001496a9bc4; asc Ij ;; InnoDB: record PHYSICAL RECORD: n_fields 3; compact format; info bits 32 0: len 30; hex 373430423831383038303830383038303830383038303830383038304436; asc 740B818080808080808080808080D6; (total 32 bytes); 1: SQL NULL; 2: len 8; hex 80000001496a9bc4; asc Ij ;; space 1053 offset 20726017 (1 records, index id 3456) InnoDB: Submit a detailed bug report to http://bugs.mysql.com mysql> select IST.SCHEMA, IST.NAME, ISI.NAME from INNODB_SYS_TABLES IST INNER JOIN INNODB_SYS_INDEXES ISI ON IST.TABLE_ID = ISI.TABLE_ID and ISI.INDEX_ID=3456; +--------+-----------------+---------------------+ | SCHEMA | NAME | NAME | +--------+-----------------+---------------------+ | asp | trace_poll_ejb3 | idx_customerid_mark | +--------+-----------------+---------------------+ 1 row in set (0.00 sec)
[26 Mar 2013 20:46]
Arnaud Adant
Are you sure to run with innodb_change_buffering = inserts ? The problem should be fixed with this bug fix if you still want to run with innodb_change_buffering = all. Bug 16183892 - INNODB PURGE BUFFERING IS NOT CRASH-SAFE
[27 Mar 2013 1:46]
zhai weixiang
actually , bug#66819 was not fixed completely. Just read the last comment of bug#66819
[27 Mar 2013 9:07]
Bart Verwilst
An "alter table x engine=innodb" seems to have done the trick for this index. No more errors in the last 10 hours.. I'm not using the flag because it sounds hackish, i would rather just have it work out of the box :D
[29 Aug 2013 7:11]
Marko Mäkelä
Bug#69979 is one more possible root cause for this bug.
[20 Nov 2014 6:33]
Marko Mäkelä
Possible root cause: Bug#73767 "Unable to purge a record" with ibuf and varchar fields containing spaces
