MySQL Bugs: #58895: InnoDB: Failing assertion: UT_LIST_GET_LEN(buf_pool->flush

Bug #58895	InnoDB: Failing assertion: UT_LIST_GET_LEN(buf_pool->flush_list) == 0
Submitted:	13 Dec 2010 10:27	Modified:	12 Jan 2011 17:38
Reporter:	Vasil Dimov	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S2 (Serious)
Version:	5.6	OS:	Any
Assigned to:	Inaam Rana	CPU Architecture:	Any

Description:
From http://pb2.norway.sun.com/?template=show_pushes&branch=mysql-trunk-innodb-pb2 (on linux x86_64 max)

main.group_min_max_innodb [ fail ]
        Test ended at 2010-12-12 13:47:34

CURRENT_TEST: main.group_min_max_innodb
101212 15:47:32 InnoDB: The InnoDB memory heap is disabled
101212 15:47:32 InnoDB: Mutexes and rw_locks use GCC atomic builtins
101212 15:47:32 InnoDB: Compressed tables use zlib 1.2.3
101212 15:47:32 InnoDB: Initializing buffer pool, size = 8.0M
101212 15:47:32 InnoDB: Completed initialization of buffer pool
101212 15:47:32 InnoDB: highest supported file format is Barracuda.
101212 15:47:34  InnoDB: Assertion failure in thread 1210497344 in file /export/home3/pb2/build/sb_2-2657467-1292147995.99/mysql-5.6.1-m5/storage/innobase/buf/buf0flu.c line 2440
InnoDB: Failing assertion: UT_LIST_GET_LEN(buf_pool->flush_list) == 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.6/en/forcing-recovery.html
InnoDB: about forcing recovery.
mysqltest got signal 6
read_command_buf (0x1013720): , ('a','b','a','i121','xy1'),('a','b','a','j121','xy2'),('a','b','a','k121','xy3'),('a','b','a','l121','xy4'), ('a','b','b','m122','xy1'),('a','b','b','n122','xy2'),('a','b','b','o122','xy3'),('a','b','b','p122','xy4'), ('b','a','a','a211','xy1'),('b','a','a','b211','xy2'),('b','a','a','c211','xy3'),('b','a','a','d211','xy4'), ('b','a','b','e212','xy1'),('b','a','b','f212','xy2'),('b','a','b','g212','xy3'),('b','a','b','h212','xy4'), ('b','b','a','i221','xy1'),('b','b','a','j221','xy2'),('b','b','a','k221','xy3'),('b','b','a','l221','xy4'), ('b','b','b','m222','xy1'),('b','b','b','n222','xy2'),('b','b','b','o222','xy3'),('b','b','b','p222','xy4'), ('c','a','a','a311','xy1'),('c','a','a','b311','xy2'),('c','a','a','c311','xy3'),('c','a','a','d311','xy4'), ('c','a','b','e312','xy1'),('c','a','b','f312','xy2'),('c','a','b','g312','xy3'),('c','a','b','h312','xy4'), ('c','b','a','i321','xy1'),('c','b','a','j321','xy2'),('c','b','a','k321','xy3'),('c','b','a','l321','xy4'), ('c','b','b','m322','xy1'),('c','b','b','n322','xy2'),('c','b','b','o322','xy3'),('c','b','b','p322','xy4'), ('d','a','a','a411','xy1'),('d','a','a','b411','xy2'),('d','a','a','c411','xy3'),('d','a','a','d411','xy4'), ('d','a','b','e412','xy1'),('d','a','b','f412','xy2'),('d','a','b','g412','xy3'),('d','a','b','h412','xy4'), ('d','b','a','i421','xy1'),('d','b','a','j421','xy2'),('d','b','a','k421','xy3'),('d','b','a','l421','xy4'), ('d','b','b','m422','xy1'),('d','b','b','n422','xy2'),('d','b','b','o422','xy3'),('d','b','b','p422','xy4'), ('a','a','a','a111','xy1'),('a','a','a','b111','xy2'),('a','a','a','c111','xy3'),('a','a','a','d111','xy4'), ('a','a','b','e112','xy1'),('a','a','b','f112','xy2'),('a','a','b','g112','xy3'),('a','a','b','h112','xy4'), ('a','b','a','i121','xy1'),('a','b','a','j121','xy2'),('a','b','a','k121','xy3'),('a','b','a','l121','xy4'), ('a','b','b','m122','xy1'),('a','b','b','n122','xy2'),('a','b','b','o122','xy3'),('a','b','b','p122','xy4'), ('b','a','a','a211','xy1'),('b','a','a','b211','xy2'),('b','a','a','c211','xy3'),('b','a','a','d211','xy4'), ('b','a','b','e212','xy1'),('b','a','b','f212','xy2'),('b','a','b','g212','xy3'),('b','a','b','h212','xy4'), ('b','b','a','i221','xy1'),('b','b','a','j221','xy2'),('b','b','a','k221','xy3'),('b','b','a','l221','xy4'), ('b','b','b','m222','xy1'),('b','b','b','n222','xy2'),('b','b','b','o222','xy3'),('b','b','b','p222','xy4'), ('c','a','a','a311','xy1'),('c','a','a','b311','xy2'),('c','a','a','c311','xy3'),('c','a','a','d311','xy4'), ('c','a','b','e312','xy1'),('c','a','b','f312','xy2'),('c','a','b','g312','xy3'),('c','a','b','h312','xy4'), ('c','b','a','i321','xy1'),('c','b','a','j321','xy2'),('c','b','a','k321','xy3'),('c','b','a','l321','xy4'), ('c','b','b','m322','xy1'),('c','b','b','n322','xy2'),('c','b','b','o322','xy3'),('c','b','b','p322','xy4'), ('d','a','a','a411','xy1'),('d','a','a','b411','xy2'),('d','a','a','c411','xy3'),('d','a','a','d411','xy4'), ('d','a','b','e412','xy1'),('d','a','b','f412','xy2'),('d','a','b','g412','xy3'),('d','a','b','h412','xy4'), ('d','b','a','i421','xy1'),('d','b','a','j421','xy2'),('d','b','a','k421','xy3'),('d','b','a','l421','xy4'), ('d','b','b','m422','xy1'),('d','b','b','n422','xy2'),('d','b','b','o422','xy3'),('d','b','b','p422','xy4')
mysqltest got signal 11
read_command_buf (0x1013720): , ('a','b','a','i121','xy1'),('a','b','a','j121','xy2'),('a','b','a','k121','xy3'),('a','b','a','l121','xy4'), ('a','b','b','m122','xy1'),
...
('d','b','a','l421','xy4'), ('d','b','b','m422','xy1'),('d','b','b','n422','xy2'),('d','b','b','o422','xy3'),('d','b','b','p422','xy4')

 - saving '/export/home2/pb2/test/sb_1-2657502-1292148363.25/mysql-5.6.1-m5-linux-x86_64-test/mysql-test/var-emebbed/log/main.group_min_max_innodb/' to '/export/home2/pb2/test/sb_1-2657502-1292148363.25/mysql-5.6.1-m5-linux-x86_64-test/mysql-test/var-emebbed/log/main.group_min_max_innodb/'

Retrying test main.group_min_max_innodb, attempt(2/3)...

main.group_min_max_innodb                [ retry-pass ]    749

Retrying test main.group_min_max_innodb, attempt(3/3)...

main.group_min_max_innodb                [ retry-pass ]    785

How to repeat:
This test first failed with vasil.dimov@oracle.com-20101212092901-yvlhd9xby5xtc3fn but given the sporadic failure, the bug may have been there earlier.

Another non-deterministic failure with the same assertion failure (same pb2 run/same platform):

innodb.innodb_bug21704 [ fail ]
        Test ended at 2010-12-12 13:50:30

CURRENT_TEST: innodb.innodb_bug21704
101212 15:50:28 InnoDB: The InnoDB memory heap is disabled
101212 15:50:28 InnoDB: Mutexes and rw_locks use GCC atomic builtins
101212 15:50:28 InnoDB: Compressed tables use zlib 1.2.3
101212 15:50:28 InnoDB: Initializing buffer pool, size = 8.0M
101212 15:50:28 InnoDB: Completed initialization of buffer pool
101212 15:50:28 InnoDB: highest supported file format is Barracuda.
101212 15:50:29  InnoDB: Error: in ALTER TABLE `test`.`t1`
InnoDB: has or is referenced in foreign key constraints
InnoDB: which are not compatible with the new table definition.
101212 15:50:29  InnoDB: Error: table `test`.`t1` does not exist in the InnoDB internal
InnoDB: data dictionary though MySQL is trying to drop it.
InnoDB: Have you copied the .frm file of the table to the
InnoDB: MySQL database directory from another database?
InnoDB: You can look for further help from
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/innodb-troubleshooting.html
101212 15:50:29  InnoDB: Error: in ALTER TABLE `test`.`t2`
InnoDB: has or is referenced in foreign key constraints
InnoDB: which are not compatible with the new table definition.
101212 15:50:29  InnoDB: Error: table `test`.`t2` does not exist in the InnoDB internal
InnoDB: data dictionary though MySQL is trying to drop it.
InnoDB: Have you copied the .frm file of the table to the
InnoDB: MySQL database directory from another database?
InnoDB: You can look for further help from
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/innodb-troubleshooting.html
101212 15:50:29  InnoDB: Error: in ALTER TABLE `test`.`t3`
InnoDB: has or is referenced in foreign key constraints
InnoDB: which are not compatible with the new table definition.
101212 15:50:29  InnoDB: Error: table `test`.`t3` does not exist in the InnoDB internal
InnoDB: data dictionary though MySQL is trying to drop it.
InnoDB: Have you copied the .frm file of the table to the
InnoDB: MySQL database directory from another database?
InnoDB: You can look for further help from
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/innodb-troubleshooting.html
101212 15:50:29  InnoDB: Error: in ALTER TABLE `test`.`t3`
InnoDB: has or is referenced in foreign key constraints
InnoDB: which are not compatible with the new table definition.
101212 15:50:29  InnoDB: Error: table `test`.`t3` does not exist in the InnoDB internal
InnoDB: data dictionary though MySQL is trying to drop it.
InnoDB: Have you copied the .frm file of the table to the
InnoDB: MySQL database directory from another database?
InnoDB: You can look for further help from
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/innodb-troubleshooting.html
101212 15:50:29  InnoDB: Assertion failure in thread 1204214080 in file /export/home3/pb2/build/sb_2-2657467-1292147995.99/mysql-5.6.1-m5/storage/innobase/buf/buf0flu.c line 2440
InnoDB: Failing assertion: UT_LIST_GET_LEN(buf_pool->flush_list) == 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.6/en/forcing-recovery.html
InnoDB: about forcing recovery.
mysqltest got signal 6
read_command_buf (0x1013720): 
mysqltest got signal 11
read_command_buf (0x1013720):

 - saving '/export/home2/pb2/test/sb_1-2657502-1292148363.25/mysql-5.6.1-m5-linux-x86_64-test/mysql-test/var-emebbed/log/innodb.innodb_bug21704/' to '/export/home2/pb2/test/sb_1-2657502-1292148363.25/mysql-5.6.1-m5-linux-x86_64-test/mysql-test/var-emebbed/log/innodb.innodb_bug21704/'

Retrying test innodb.innodb_bug21704, attempt(2/3)...

innodb.innodb_bug21704                   [ retry-pass ]    737

Retrying test innodb.innodb_bug21704, attempt(3/3)...

innodb.innodb_bug21704                   [ retry-pass ]    702

Another one, same pb2 run, but on win x86_64 debug_max

main.innodb_icp w2 [ fail ]
        Test ended at 2010-12-12 12:57:57

CURRENT_TEST: main.innodb_icp
101212 12:57:34 InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
101212 12:57:34 InnoDB: The InnoDB memory heap is disabled
101212 12:57:34 InnoDB: Mutexes and rw_locks use Windows interlocked functions
101212 12:57:34 InnoDB: Compressed tables use zlib 1.2.3
101212 12:57:34 InnoDB: Initializing buffer pool, size = 8.0M
101212 12:57:34 InnoDB: Completed initialization of buffer pool
101212 12:57:35 InnoDB: highest supported file format is Barracuda.
101212 12:57:56  InnoDB: Assertion failure in thread 6664 in file .\buf\buf0flu.c line 2440
InnoDB: Failing assertion: UT_LIST_GET_LEN(buf_pool->flush_list) == 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.6/en/forcing-recovery.html
InnoDB: about forcing recovery.
mysqltest got exception 0xc0000005
read_command_buf (0000000140A1F4F0): =
conn->name (DDDDDDDDDDDDDDDD): =is an invalid string pointer
conn->cur_query (DDDDDDDDDDDDDDDD): =is an invalid string pointer
Attempting backtrace...
000000013FDA94F5    mysqltest_embedded.exe!buf_flush_page_cleaner_thread()[buf0flu.c:2440]
000000007762BE3D    kernel32.dll!BaseThreadInitThunk()
0000000077836A51    ntdll.dll!RtlUserThreadStart()
Writing a core file...
Minidump written to G:\pb2\test\sb_1-2657687-1292150011.37\mysql-5.6.1-m5-win-x86_64-test\mysql-test\mysqltest_embedded.dmp

mysqltest failed with unexpected return code 5

 - saving 'G:/pb2/test/sb_1-2657687-1292150011.37/mysql-5.6.1-m5-win-x86_64-test/mysql-test/var-emebbed/2/log/main.innodb_icp/' to 'G:/pb2/test/sb_1-2657687-1292150011.37/mysql-5.6.1-m5-win-x86_64-test/mysql-test/var-emebbed/log/main.innodb_icp/'
 - found 'mysqltest_embedded.dmp', moving it to 'G:/pb2/test/sb_1-2657687-1292150011.37/mysql-5.6.1-m5-win-x86_64-test/mysql-test/var-emebbed/log/main.innodb_icp'
 - found 'mysqltest_embedded.dmp' (0/5)

Trying 'cdb' to get a backtrace
OS debug symbols will be downloaded and stored in C:\cdb_symbols.
You can control the location of symbol cache with _NT_SYMBOL_PATH
environment variable. Please refer to Microsoft KB article
http://support.microsoft.com/kb/311503  for details about _NT_SYMBOL_PATH
-------------------------------------------------------------------------
Output from cdb follows. Faulting thread is printed twice,with and without function parameters
Search for STACK_TEXT to see the stack trace of 
the faulting thread. Callstacks of other threads are printed after it.

Microsoft (R) Windows Debugger Version 6.11.0001.402 AMD64
Copyright (c) Microsoft Corporation. All rights reserved.

Loading Dump File [G:\pb2\test\sb_1-2657687-1292150011.37\mysql-5.6.1-m5-win-x86_64-test\mysql-test\var-emebbed\log\main.innodb_icp\mysqltest_embedded.dmp]
User Mini Dump File: Only registers, stack and portions of memory are available

Symbol search path is: C:\Windows\System32;G:\pb2\test\sb_1-2657687-1292150011.37\mysql-5.6.1-m5-win-x86_64-test\libmysqld\examples\Debug;.;srv*C:\cdb_symbols*http://msdl.microsoft.com/download/symbols
Executable search path is: C:\Windows\System32;G:\pb2\test\sb_1-2657687-1292150011.37\mysql-5.6.1-m5-win-x86_64-test\libmysqld\examples\Debug;.
Windows Server 2008/Windows Vista Version 6002 (Service Pack 2) MP (8 procs) Free x64
Product: Server, suite: Enterprise TerminalServer SingleUserTS
Machine Name:
Debug session time: Sun Dec 12 12:57:56.000 2010 (GMT+1)
System Uptime: not available
Process Uptime: 0 days 0:00:22.000
.............................
This dump file has an exception of interest stored in it.
The stored exception information can be accessed via .ecxr.
(2528.1a08): Access violation - code c0000005 (first/second chance not available)
ntdll!ZwGetContextThread:
             ret
0:008> cdb: Reading initial command '!sym prompts off; !analyze -v; .ecxr; !for_each_frame dv /t;!uniqstack -p;q'
quiet mode - symbol prompts off

FAULTING_IP: 
mysqltest_embedded!buf_flush_page_cleaner_thread+525 [g:\pb2\build\sb_0-2657467-1292148950.7\mysql-5.6.1-m5-win-x86_64\storage\innobase\buf\buf0flu.c @ 2440]
       cmp     qword ptr [r11],0

EXCEPTION_RECORD:  ffffffffffffffff -- (.exr 0xffffffffffffffff)
ExceptionAddress: 000000013fda94f5 (mysqltest_embedded!buf_flush_page_cleaner_thread)
   ExceptionCode: c0000005 (Access violation)
  ExceptionFlags: 00000000
NumberParameters: 2
   Parameter[0]: 0000000000000000
   Parameter[1]: 0000000000000000
Attempt to read from address 0000000000000000

DEFAULT_BUCKET_ID:  NULL_POINTER_READ

PROCESS_NAME:  mysqltest_embedded.exe

ERROR_CODE: (NTSTATUS) 0xc0000005 - The instruction at 0x%08lx referenced memory at 0x%08lx. The memory could not be %s.

EXCEPTION_CODE: (NTSTATUS) 0xc0000005 - The instruction at 0x%08lx referenced memory at 0x%08lx. The memory could not be %s.

EXCEPTION_PARAMETER1:  0000000000000000

EXCEPTION_PARAMETER2:  0000000000000000

READ_ADDRESS:  0000000000000000 

FOLLOWUP_IP: 
mysqltest_embedded!buf_flush_page_cleaner_thread+525 [g:\pb2\build\sb_0-2657467-1292148950.7\mysql-5.6.1-m5-win-x86_64\storage\innobase\buf\buf0flu.c @ 2440]
       cmp     qword ptr [r11],0

FAULTING_THREAD:  0000000000001a08

PRIMARY_PROBLEM_CLASS:  NULL_POINTER_READ

BUGCHECK_STR:  APPLICATION_FAULT_NULL_POINTER_READ

LAST_CONTROL_TRANSFER:  from 000000007762be3d to 000000013fda94f5

STACK_TEXT:  
mysqltest_embedded!buf_flush_page_cleaner_thread [g:\pb2\build\sb_0-2657467-1292148950.7\mysql-5.6.1-m5-win-x86_64\storage\innobase\buf\buf0flu.c @ 2440]
kernel32!BaseThreadInitThunk
ntdll!RtlUserThreadStart

STACK_COMMAND:  ~8s; .ecxr ; kb

SYMBOL_STACK_INDEX:  0

SYMBOL_NAME:  mysqltest!buf_flush_page_cleaner_thread+525

FOLLOWUP_NAME:  MachineOwner

MODULE_NAME: mysqltest_embedded

IMAGE_NAME:  mysqltest_embedded.exe

DEBUG_FLR_IMAGE_TIMESTAMP:  4d04a405

FAILURE_BUCKET_ID:  NULL_POINTER_READ_c0000005_mysqltest_embedded.exe!buf_flush_page_cleaner_thread

BUCKET_ID:  X64_APPLICATION_FAULT_NULL_POINTER_READ_mysqltest!buf_flush_page_cleaner_thread+525

WATSON_STAGEONE_URL:  http://watson.microsoft.com/StageOne/mysqltest_embedded_exe/5_6_1_0/4d04a405/mysqltest_emb...

Followup: MachineOwner
---------

rax=0000000000000000 rbx=0000000000000000 rcx=0000000140aef3f0
rdx=0000000000000000 rsi=0000000000000000 rdi=0000000003d4fa50
rip=000000013fda94f5 rsp=0000000003d4f9d0 rbp=0000000000000000
 r8=0000000000000000  r9=0000000000000000 r10=63657220676e6963
r11=0000000000000000 r12=0000000000000000 r13=0000000000000000
r14=0000000000000000 r15=0000000000000000
iopl=0         nv up ei pl nz na po nc
cs=0033  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00010206
mysqltest_embedded!buf_flush_page_cleaner_thread:
       cmp     qword ptr [r11],0 ds:00000000`00000000=????????????????
...

Retrying test main.innodb_icp, attempt(2/3)...

main.innodb_icp                          w2 [ retry-pass ]  15230

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/126710

3383 Inaam Rana	2010-12-13
      bug#58895 InnoDB: Failing assertion: UT_LIST_GET_LEN(buf_pool->flush_list) == 0
      
      A race introduced by page_cleaner patch where it is possible to miss
      the final round of flushing if the page_cleaner has an unfinished batch
      already running from previous phase.
      
      Approved by: Sunny

Pushed into mysql-trunk 5.6.1 (revid:alexander.nozdrin@oracle.com-20101222212842-y0t3ibtd32wd9qaw) (version source revid:alexander.nozdrin@oracle.com-20101222212842-y0t3ibtd32wd9qaw) (merge vers: 5.6.1) (pib:24)

See bug 85585