MySQL Bugs: #45986: InnoDB: Assertion failure in thread 6472 in file .\buf\buf0flu.c line 279

Bug #45986	InnoDB: Assertion failure in thread 6472 in file .\buf\buf0flu.c line 279
Submitted:	7 Jul 2009 3:16	Modified:	8 Jul 2009 9:51
Reporter:	David Chell	Email Updates:
Status:	Can't repeat	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S1 (Critical)
Version:	5.1.36-community	OS:	Any (Windows Server 2008 x64)
Assigned to:		CPU Architecture:	Any

Description:
I am trying to archive a couple of table to another database. These tables contain 220239 and 1227428 records respectively. I am running an INSERT...SELECT query to copy the data using a date range (all records where the date < 01-01-2009). These statements are in a stored procedure called ArchiveHistory. I've set up some batch files so this can be run from the command line on a scheduled task.

In MySql Server version 5.0.51a it would sometimes complete successfully and sometimes hang on the second INSERT...SELECT. If I did a SELECT COUNT(*) FROM incidentarchivedb.tFieldHistoryArchive it would return a count indicating all the rows had been inserted, but a SHOW PROCESSLIST would show that the thread is still processing the INSERT...SELECT statement. 

I then upgraded to 5.1.36 edition, with the data files in a new directory and loaded the data into the database from a backup. Now when I run the ArchiveHistory procedure from the batch file MySQL server crashes and the error in the log is:

InnoDB: Assertion failure in thread 6472 in file .\buf\buf0flu.c line 279.

The database schemas and data and batch files can be downloaded from www.qualitech.co.nz/bugreport.7z.

Please let me know if you need any more information.

Regards.
David Chell

How to repeat:
Create new databases using the attached schema and data and run the ArchiveHistory stored procedure.

Files can be downloaded from www.qualitech.co.nz/bugreport.rar. For some reason I couldn't get IIS to serve up a 7z file - just gave error 404.

Thank you for the problem report. Formally this assertion failure refers to memory corruption. Please, cehck for any related reports in the Event Log.

The only similar bug report so far is http://bugs.mysql.com/34076 (for 5.0.x), but it is still not clear if there is any other reason than memory problem for it.

Here is an excerpt from the error log since startup immediately prior to the occurrence of the problem:

090707 13:23:16  InnoDB: Started; log sequence number 0 0
090707 13:23:16 [Note] Event Scheduler: Loaded 0 events
090707 13:23:16 [Note] C:\Program Files\MySQL\MySQL Server 5.1\bin\mysqld: ready for connections.
Version: '5.1.36-community'  socket: ''  port: 3306  MySQL Community Server (GPL)
090707 13:24:43 [Note] Plugin 'FEDERATED' is disabled.
090707 13:24:43  InnoDB: Started; log sequence number 0 46409
090707 13:24:43 [Note] Event Scheduler: Loaded 0 events
090707 13:24:43 [Note] C:\Program Files\MySQL\MySQL Server 5.1\bin\mysqld: ready for connections.
Version: '5.1.36-community'  socket: ''  port: 3306  MySQL Community Server (GPL)
InnoDB: Wrong owned count 15, 2, rec 3937
090707 14:35:31  InnoDB: Page dump in ascii and hex (16384 bytes):
 len 16384; hex 
.... (contents of page dump removed)
InnoDB: End of page dump
090707 14:35:31  InnoDB: Page checksum 1208085742, prior-to-4.0.14-form checksum 408435803
InnoDB: stored checksum 1208085742, prior-to-4.0.14-form stored checksum 408435803
InnoDB: Page lsn 0 731080078, low 4 bytes of lsn at page end 731080078
InnoDB: Page number (if stored to page already) 19748,
InnoDB: space id (if created with >= MySQL-4.1.1 and stored already) 0
InnoDB: Page may be an index page where index id is 0 2267
InnoDB: (index "PRIMARY" of table "incidentarchivedb"."tincidenthistoryarchive")
090707 14:35:31  InnoDB: Apparent corruption of an index page n:o 19748 in space 0
InnoDB: to be written to data file. We intentionally crash server
InnoDB: to prevent corrupt data from ending up in data
InnoDB: files.
090707 14:35:31  InnoDB: Assertion failure in thread 6472 in file .\buf\buf0flu.c line 279
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.
090707 14:35:31 - mysqld got exception 0xc0000005 ;
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=57671680
read_buffer_size=65536
max_used_connections=8
max_threads=100
threads_connected=7
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 89213 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd: 0x10279010
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...
0000000140392688    mysqld.exe!buf_flush_buffered_writes()[buf0flu.c:279]
0000000140393135    mysqld.exe!buf_flush_try_page()[buf0flu.c:714]
00000001403933E7    mysqld.exe!buf_flush_try_neighbors()[buf0flu.c:803]
0000000140393610    mysqld.exe!buf_flush_batch()[buf0flu.c:923]
000000014034C4FB    mysqld.exe!log_preflush_pool_modified_pages()[log0log.c:1584]
000000014034CF95    mysqld.exe!log_checkpoint_margin()[log0log.c:2095]
000000014034D1EE    mysqld.exe!log_check_margins()[log0log.c:3004]
000000014034DEBA    mysqld.exe!log_free_check()[log0log.ic:398]
00000001403A281A    mysqld.exe!row_ins_index_entry_low()[row0ins.c:1992]
00000001403A2CA7    mysqld.exe!row_ins_index_entry()[row0ins.c:2182]
00000001403A2E49    mysqld.exe!row_ins_index_entry_step()[row0ins.c:2262]
00000001403A301F    mysqld.exe!row_ins()[row0ins.c:2393]
00000001403A317C    mysqld.exe!row_ins_step()[row0ins.c:2506]
000000014033C916    mysqld.exe!row_insert_for_mysql()[row0mysql.c:1163]
000000014032EFE2    mysqld.exe!ha_innobase::write_row()[ha_innodb.cc:3765]
000000014004CD36    mysqld.exe!handler::ha_write_row()[handler.cc:4599]
000000014018B897    mysqld.exe!write_record()[sql_insert.cc:1557]
000000014018CD5B    mysqld.exe!select_insert::send_data()[sql_insert.cc:3117]
00000001401C86C9    mysqld.exe!end_send()[sql_select.cc:11993]
00000001401C7C84    mysqld.exe!evaluate_join_record()[sql_select.cc:11254]
00000001401CF31B    mysqld.exe!sub_select()[sql_select.cc:11144]
00000001401C7C84    mysqld.exe!evaluate_join_record()[sql_select.cc:11254]
00000001401CF31B    mysqld.exe!sub_select()[sql_select.cc:11144]
00000001401E827A    mysqld.exe!do_select()[sql_select.cc:10895]
00000001401E966B    mysqld.exe!JOIN::exec()[sql_select.cc:2200]
00000001401E9E5A    mysqld.exe!mysql_select()[sql_select.cc:2388]
00000001401EA3A6    mysqld.exe!handle_select()[sql_select.cc:268]
00000001401A528F    mysqld.exe!mysql_execute_command()[sql_parse.cc:3203]
000000014013FBE8    mysqld.exe!sp_instr_stmt::exec_core()[sp_head.cc:2908]
0000000140143395    mysqld.exe!sp_lex_keeper::reset_lex_and_exec_core()[sp_head.cc:2735]
0000000140143596    mysqld.exe!sp_instr_stmt::execute()[sp_head.cc:2851]
0000000140144FC5    mysqld.exe!sp_head::execute()[sp_head.cc:1255]
000000014014638F    mysqld.exe!sp_head::execute_procedure()[sp_head.cc:1983]
00000001401A7144    mysqld.exe!mysql_execute_command()[sql_parse.cc:4359]
00000001401A93A6    mysqld.exe!mysql_parse()[sql_parse.cc:5937]
00000001401AA0DA    mysqld.exe!dispatch_command()[sql_parse.cc:1215]
00000001401AB1A7    mysqld.exe!do_command()[sql_parse.cc:854]
000000014024DE37    mysqld.exe!handle_one_connection()[sql_connect.cc:1127]
00000001402BF9A5    mysqld.exe!pthread_start()[my_winthread.c:85]
00000001403D34D7    mysqld.exe!_callthreadstart()[thread.c:295]
00000001403D35A5    mysqld.exe!_threadstart()[thread.c:275]
0000000076C0466D    kernel32.dll!BaseThreadInitThunk()
0000000076D38791    ntdll.dll!RtlUserThreadStart()
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
thd->query at 000000000EE16858=INSERT INTO incidentarchivedb.tFieldhistoryArchive    (FieldHistoryID, IncidentHistoryID, FieldID, LongData, OldValue, LongOldValue, NewValue, LongNewValue,UpdateType, DataType)

SELECT FieldHistoryID, fh.IncidentHistoryID, FieldID, LongData, OldValue, LongOldValue, NewValue, LongNewValue, UpdateType, DataType

FROM tIncidentHistory ih INNER JOIN tFieldHistory fh ON ih.IncidentHistoryID = fh.IncidentHistoryID

WHERE IncidentHistoryDate >  NAME_CONST('lastArchiveDate',_binary'2000-01-01 00:00:00' COLLATE 'binary') AND IncidentHistoryDate <  NAME_CONST('ArchiveDate',_binary'2009-01-01 00:00:00' COLLATE 'binary')
thd->thread_id=57
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.

Thank you for the feedback.

Have you run mysql_upgrade?

I wouldn't have thought that was necessary since I used the new databse created during the install of 5.1 and loaded the data from a backup. But I ran it anyway - it reported OK on all tables, now I can no longer reproduce the problem, I have run the procedure 4 times in succession with no fault. I guess this means we can close the bug report.

Thank you for the feedback.

Closed as "Can't repeat". If you meet same problem again feel free to reopen the report.