Bug #47931 assert upon startup : "frag_n_used > 0"
Submitted: 9 Oct 2009 8:26 Modified: 11 Oct 2009 5:35
Reporter: Richlv - Email Updates:
Status: Can't repeat Impact on me:
None 
Category:MySQL Server Severity:S2 (Serious)
Version:5.1.39 OS:Linux (slackware 13.0)
Assigned to: CPU Architecture:Any
Tags: assert, frag_n_used

[9 Oct 2009 8:26] Richlv -
Description:
starting up produces the following in error log :

091009 11:20:14 mysqld_safe Starting mysqld daemon with databases from /usr/local/var
InnoDB: Log scan progressed past the checkpoint lsn 5 4179754997
091009 11:20:19  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 5 4181292054
InnoDB: 1 transaction(s) which must be rolled back or cleaned up
InnoDB: in total 8617 row operations to undo
InnoDB: Trx id counter is 0 200581120
091009 11:20:45  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
InnoDB: Last MySQL binlog file position 0 57451061, file name ./mysql-bin.000010
InnoDB: Starting in background the rollback of uncommitted transactions
091009 11:20:50  InnoDB: Rolling back trx with id 0 200580842, 8617 rows to undo

InnoDB: Progress in percents: 1 2 3 4 5 6091009 11:20:50  InnoDB: Assertion failure in thread 3016596368 in file fsp/fsp0fsp.c line 1593
InnoDB: Failing assertion: frag_n_used > 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.1/en/forcing-recovery.html
InnoDB: about forcing recovery.
091009 11:20:50 - 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=262144
max_used_connections=0
max_threads=151
threads_connected=0
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 133306 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

How to repeat:
happens every startup with this database
[9 Oct 2009 9:16] Valeriy Kravchuk
Thank you for the problem report. Please, upload your entire error log. I had never seen this assertion (it is in fsp_free_page() function that is used to free single page of space)...
[9 Oct 2009 9:26] Richlv -
that is the whole error log, there is nothing more logged.
[9 Oct 2009 9:48] Valeriy Kravchuk
Sorry, I don't believe you. Normal log can NOT start with:

091009 11:20:14 mysqld_safe Starting mysqld daemon with databases from /usr/local/var
InnoDB: Log scan progressed past the checkpoint lsn 5 4179754997
091009 11:20:19  InnoDB: Database was not shut down normally!

There should be infromation about previous startup, for example. So, you either cleared the log somehow before this startup, or do not send it entirely. We need to know what happend before this startup attempt. Check also your OS logs (/var/log/messages etc) for possible hardware failure messages.
[9 Oct 2009 9:51] Richlv -
true, previous logfile entries were cleared. there are no hardware failures logged anywhere.

actually, turns out i had grabbed logfile before it was fully printed... a moment later backtrace was printed, which might be useful ;)

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 0x30000
/usr/local/libexec/mysqld(my_print_stacktrace+0x1d) [0x847f35d]
/usr/local/libexec/mysqld(handle_segfault+0x2fa) [0x81cbb9a]
[0xffffe400]
/lib/libc.so.6(abort+0x188) [0xb7d3ee08]
/usr/local/libexec/mysqld [0x838591b]
/usr/local/libexec/mysqld [0x83f9f9e]
/usr/local/libexec/mysqld(trx_undo_truncate_end+0x548) [0x83fc218]
/usr/local/libexec/mysqld(trx_roll_pop_top_rec_of_trx+0x97a) [0x83f329a]
/usr/local/libexec/mysqld(row_undo_step+0x282) [0x83d7f42]
/usr/local/libexec/mysqld(que_run_threads+0x554) [0x83bd484]
/usr/local/libexec/mysqld(trx_rollback_or_clean_all_without_sess+0x357) [0x83f1db7]
/lib/libpthread.so.0 [0xb7ff7310]
/lib/libc.so.6(clone+0x5e) [0xb7df4bee]
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.
091009 12:48:40 mysqld_safe mysqld from pid file /usr/local/var/rich.pid ended
[9 Oct 2009 10:01] Valeriy Kravchuk
The only bug with a similar stack trace (although other assertion failed) is http://bugs.mysql.com/bug.php?id=15717. Still, OS/hardware failure is the most probable reason, according to Heikki. Please, double check.
[9 Oct 2009 10:30] Richlv -
well, i just thought that asserting is bad in any case (and i haven't found any hardware issues). as i did not have any critical databases there and the ones i was interested in could be dumped with innodb_force_recovery = 3, i just nuked the old data, which made mysql happy. feel free to close this report.
[11 Oct 2009 5:35] Sveta Smirnova
Thank you for the feedback.

Closing as "Can't repeat" for now. If you meet this again don't clean up error log file, check your disk and RAM (memtest is good for RAM checking) and reopen the report in case if problem not in hardware.