InnoDB failing assertion buf_page_in_file(bpage) and restarts

[Damian Bogdanov]

Hi,

On a server we're experiencing the following assertion failure:

101014 10:14:08 InnoDB: Assertion failure in thread 139663641130768 in file buf/buf0buf.c line 1645
InnoDB: Failing assertion: buf_page_in_file(bpage)
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.
101014 10:14: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=8388608
read_buffer_size=1048576
max_used_connections=71
max_threads=200
threads_connected=63
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 1853560 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd: 0x7f05f4030ab0
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 = 0x7f05f9b7aeb0 thread_stack 0x80000
/usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x88958e]
/usr/sbin/mysqld(handle_segfault+0x35c)[0x5cda8c]
/lib/libpthread.so.0(+0xef60)[0x7f06d1f07f60]
/lib/libc.so.6(gsignal+0x35)[0x7f06d0ccd165]
/lib/libc.so.6(abort+0x180)[0x7f06d0ccff70]
/usr/sbin/mysqld[0x7f1101]
/usr/sbin/mysqld[0x7f14ad]
/usr/sbin/mysqld[0x7dcf61]
/usr/sbin/mysqld[0x7dd54c]
/usr/sbin/mysqld[0x7a197d]
/usr/sbin/mysqld[0x7a3b8a]
/usr/sbin/mysqld[0x74a2e6]
/usr/sbin/mysqld(_ZN7handler16read_range_firstEPK12st_key_rangeS2_bb+0xbe)[0x6a703e]
/usr/sbin/mysqld(_ZN7handler22read_multi_range_firstEPP18st_key_multi_rangeS1_jbP17st_handler_buffer+0xce)[0x6a716e]
/usr/sbin/mysqld(_ZN18QUICK_RANGE_SELECT8get_nextEv+0x127)[0x68c797]
/usr/sbin/mysqld[0x6a22e1]
/usr/sbin/mysqld(_Z12mysql_updateP3THDP10TABLE_LISTR4ListI4ItemES6_PS4_jP8st_ordery15enum_duplicatesb+0x7e2)[0x654b22]
/usr/sbin/mysqld(_Z21mysql_execute_commandP3THD+0xb2f)[0x5d9b5f]
/usr/sbin/mysqld(_ZN18Prepared_statement7executeEP6Stringb+0x3ad)[0x64c4dd]
/usr/sbin/mysqld(_ZN18Prepared_statement12execute_loopEP6StringbPhS2_+0x8a)[0x64daea]
/usr/sbin/mysqld(_Z19mysqld_stmt_executeP3THDPcj+0x12a)[0x64e9da]
/usr/sbin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x107e)[0x5e068e]
/usr/sbin/mysqld(_Z10do_commandP3THD+0x122)[0x5e0cc2]
/usr/sbin/mysqld(handle_one_connection+0x447)[0x5d4987]
/lib/libpthread.so.0(+0x68ba)[0x7f06d1eff8ba]
/lib/libc.so.6(clone+0x6d)[0x7f06d0d6a02d]
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
thd->query at 0x7f05f417d758 is an invalid pointer
thd->thread_id=22827
thd->killed=NOT_KILLED
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: my_new.cc:51: int __cxa_pure_virtual(): Assertion `! "Aborted: pure virtual method called."' failed.
101014 10:14:09 [Note] Plugin 'FEDERATED' is disabled.
InnoDB: The InnoDB memory heap is disabled
InnoDB: Mutexes and rw_locks use GCC atomic builtins
InnoDB: Compressed tables use zlib 1.2.3.3
101014 10:14:10 InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 2081535906367
101014 10:14:10 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 2081541149184
InnoDB: Doing recovery: scanned up to log sequence number 2081546392064
InnoDB: Doing recovery: scanned up to log sequence number 2081551634944
InnoDB: Doing recovery: scanned up to log sequence number 2081556877824
InnoDB: Doing recovery: scanned up to log sequence number 2081562120704
InnoDB: Doing recovery: scanned up to log sequence number 2081567363584
InnoDB: Doing recovery: scanned up to log sequence number 2081572606464
InnoDB: Doing recovery: scanned up to log sequence number 2081577849344
InnoDB: Doing recovery: scanned up to log sequence number 2081583092224
InnoDB: Doing recovery: scanned up to log sequence number 2081588335104
InnoDB: Doing recovery: scanned up to log sequence number 2081593577984
InnoDB: Doing recovery: scanned up to log sequence number 2081598820864
InnoDB: Doing recovery: scanned up to log sequence number 2081604063744
InnoDB: Doing recovery: scanned up to log sequence number 2081609306624
InnoDB: Doing recovery: scanned up to log sequence number 2081614549504
InnoDB: Doing recovery: scanned up to log sequence number 2081619792384
InnoDB: Doing recovery: scanned up to log sequence number 2081625035264
InnoDB: Doing recovery: scanned up to log sequence number 2081630278144
InnoDB: Doing recovery: scanned up to log sequence number 2081635521024
InnoDB: Doing recovery: scanned up to log sequence number 2081640763904
InnoDB: Doing recovery: scanned up to log sequence number 2081646006784
InnoDB: Doing recovery: scanned up to log sequence number 2081651249664
InnoDB: Doing recovery: scanned up to log sequence number 2081656492544
InnoDB: Doing recovery: scanned up to log sequence number 2081661735424
InnoDB: Doing recovery: scanned up to log sequence number 2081666978304
InnoDB: Doing recovery: scanned up to log sequence number 2081672221184
InnoDB: Doing recovery: scanned up to log sequence number 2081677464064
InnoDB: Doing recovery: scanned up to log sequence number 2081682706944
InnoDB: Doing recovery: scanned up to log sequence number 2081687949824
InnoDB: Doing recovery: scanned up to log sequence number 2081688296852
101014 10:14:14 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
101014 10:16:30 Percona XtraDB (http://www.percona.com) 1.0.11-11.4 started; log sequence number 2081688296852
101014 10:16:31 [Note] Event Scheduler: Loaded 0 events
101014 10:16:31 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.1.50-rel11.4' socket: '/var/run/mysqld/mysqld.sock' port: 3306 (Percona Server (GPL), 11.4 , Revision 111)

Sometimes thd->query states a failing query, but it is completely random query, as are the crashes. Sometimes we get it 7-8 times a day, sometimes it doesn't show for a week. This happens with 5.1.42-xtradb, 5.1.47-percona, 5.1.49-percona and 5.1.50-percona on a Debian Lenny mixed with some testing packages, all mysql packages are installed via Percona repository. 5.1.42 was working most stable, and the severity of occurrence increases with server upgrades.

Also, found out that https://bugs.launchpad.net/percona-xtradb/+bug/456566 is somewhat similar to this one although it happens in buf/buf0flu.c, not in buf/buf0buf.c.

I'll try to provide more information if it's needed, but keep in mind that this is production server with 50GB+ data and the problem is not happening on any of the local test machines I've tried.

[Kevin Day (toasty)]

I also just got what appears to be the same thing, on the 5.1.54-rel12.5 FreeBSD amd64 binary:

Version: '5.1.54-rel12.5-log' socket: '/tmp/mysql.sock' port: 3306 Percona Server with XtraDB (GPL), Release 12.5, Revision 188
110114 7:15:13 InnoDB: Assertion failure in thread 34380732992 in file buf/buf0buf.c line 2102
InnoDB: Failing assertion: buf_page_in_file(bpage)
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.
110114 7:15:13 - 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=16777216
read_buffer_size=2097152
max_used_connections=49
max_threads=128
threads_connected=10
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 804188 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Assertion failed: (! "Aborted: pure virtual method called."), function __cxa_pure_virtual, file my_new.cc, line 51.

[James Braid (jamesbraid)]

We're seeing the same/similar thing. We are running 5.1.45-10.1:

110509 21:42:00 [Note] /opt/Percona-XtraDB-5.1.45-1.0.6-10.1-Linux-2.6.18-164.15
.1.el5-x86_64/libexec/mysqld: ready for connections.
Version: '5.1.45-log' socket: '/var/lib/mysql/mysql.sock' port: 3306 Percona
SQL Server (GPL), XtraDB 10.1, Revision 87

The backtrace fails to execute when we hit the assert, but here's the log entries:

110509 21:41:37 InnoDB: Assertion failure in thread 1074387280 in file buf/buf0
buf.c line 1646
InnoDB: Failing assertion: buf_page_in_file(bpage)
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.
110509 21:41:37 - 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=131072
max_used_connections=3536
max_threads=5000
threads_connected=2011
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 13030355 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd: 0x7f6e997cdd80
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...

[James Braid (jamesbraid)]

Forgot to mention, did anyone else find a solution to these assertions?

[Nenko Ivanov (zennon)]

We did not find solution but the bug stopped from happening right after we converted our tables from ROW_FORMAT=COMPRESSED to ROW_FORMAT=Compact

I guess that that's kind of solution.

[Lixun Peng (P.Linux) (plx)]

I found this bug, too.
I also used "ROW_FORMAT=COMPRESSED",
This is the message.
Percona can fix this bug?

110527 13:04:25 InnoDB: Assertion failure in thread 1597094208 in file buf/buf0buf.c line 1645
InnoDB: Failing assertion: buf_page_in_file(bpage)
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.
InnoDB: Thread 1612536128 stopped in file ./include/buf0buf.ic line 1039
110527 13:04:25 - mysqld got signal 11 ;
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=2097152
max_used_connections=70
max_threads=3000
threads_connected=50
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 12353275 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd: 0x2aaecec48000
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 = 0x5f31b100 thread_stack 0x40000
InnoDB: Thread 1522067776 stopped in file sync/sync0rw.c line 551
/usr/alibaba/mysql/libexec/mysqld(my_print_stacktrace+0x1f) [0xa0989f]
/usr/alibaba/mysql/libexec/mysqld(handle_segfault+0x368) [0x5e54a8]
/lib64/libpthread.so.0 [0x3b95a0eb10]
/usr/alibaba/mysql/libexec/mysqld [0x91f61a]
/usr/alibaba/mysql/libexec/mysqld [0x91f2c9]
/usr/alibaba/mysql/libexec/mysqld [0x90f358]
/usr/alibaba/mysql/libexec/mysqld [0x8af6af]
/usr/alibaba/mysql/libexec/mysqld [0x8add2e]
/usr/alibaba/mysql/libexec/mysqld [0x81552e]
/usr/alibaba/mysql/libexec/mysqld(handler::read_range_next()+0x57) [0x71e2b7]
/usr/alibaba/mysql/libexec/mysqld(handler::read_multi_range_next(st_key_multi_range**)+0x276) [0x71ddd6]
/usr/alibaba/mysql/libexec/mysqld(QUICK_RANGE_SELECT::get_next()+0x54) [0x6fefa4]
/usr/alibaba/mysql/libexec/mysqld [0x70fe74]
/usr/alibaba/mysql/libexec/mysqld [0x664b10]
/usr/alibaba/mysql/libexec/mysqld(JOIN::exec()+0x22f3) [0x662083]
/usr/alibaba/mysql/libexec/mysqld(mysql_select(THD*, Item***, TABLE_LIST*, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_or
der*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*)+0x19d) [0x647d8d]
/usr/alibaba/mysql/libexec/mysqld(handle_select(THD*, st_lex*, select_result*, unsigned long)+0x151) [0x647be1]
/usr/alibaba/mysql/libexec/mysqld [0x5f9721]
/usr/alibaba/mysql/libexec/mysqld(mysql_execute_command(THD*)+0x48a9) [0x5f4e59]
/usr/alibaba/mysql/libexec/mysqld(mysql_parse(THD*, char*, un...

[Yasufumi Kinoshita (yasufumi-kinoshita)]

Thank you.
But I need InnoDB symbols at the stacktrace to analyze the crash
like
/usr/sbin/mysqld[0x7f1101]
/usr/sbin/mysqld[0x7f14ad]
/usr/sbin/mysqld[0x7dcf61]
/usr/sbin/mysqld[0x7dd54c]
/usr/sbin/mysqld[0x7a197d]
/usr/sbin/mysqld[0x7a3b8a]
/usr/sbin/mysqld[0x74a2e6]
or
/usr/alibaba/mysql/libexec/mysqld [0x91f61a]
/usr/alibaba/mysql/libexec/mysqld [0x91f2c9]
/usr/alibaba/mysql/libexec/mysqld [0x90f358]
/usr/alibaba/mysql/libexec/mysqld [0x8af6af]
/usr/alibaba/mysql/libexec/mysqld [0x8add2e]
/usr/alibaba/mysql/libexec/mysqld [0x81552e]

[Stewart Smith (stewart)]

I think this may be connected to or the same bug that we're tracking through a customer issue right now. If those here could provide resolved stack traces (see mysql docs... soon to be on PS docs, but not yet) that would be very useful in trying to work out if they're the same crash.

[Stewart Smith (stewart)]

Hi all, I think that bug#802348 is a duplicate of this one - and I'm working on merging Yasufumi's fix into the next release of Percona Server. You can either directly try the branch with the fix (soon to be merged into trunk) or you may also contact us (Percona) to engage us in producing binaries for you ahead of the next scheduled release.

[Roel Van de Paar (roel11)]

See bug 1227581