InnoDB: Failing assertion: bpage->in_flush_list in file buf0lru.c line 605 | abort in buf_flush_or_remove_pages

[Roel Van de Paar]

========================= Error log:
130211 7:54:50 InnoDB: Assertion failure in thread 139821419931392 in file buf0lru.c line 605
InnoDB: Failing assertion: bpage->in_flush_list

========================= gdb :
Thread 1 (LWP 24779):
+bt
#0 0x0000003da180c60c in pthread_kill () from /lib64/libpthread.so.0
#1 0x00000000007de9a8 in my_write_core (sig=6) at /ssd/QA-16274-5.5-3/Percona-Server-5.5.28-rel29.3/mysys/stacktrace.c:433
#2 0x00000000006b3114 in handle_fatal_signal (sig=6) at /ssd/QA-16274-5.5-3/Percona-Server-5.5.28-rel29.3/sql/signal_handler.cc:249
#3 <signal handler called>
#4 0x0000003da1435935 in raise () from /lib64/libc.so.6
#5 0x0000003da14370e8 in abort () from /lib64/libc.so.6
#6 0x00000000008fdc21 in buf_flush_or_remove_pages (id=22999, buf_pool=0x3474ef8) at /ssd/QA-16274-5.5-3/Percona-Server-5.5.28-rel29.3/storage/innobase/buf/buf0lru.c:605
#7 buf_flush_dirty_pages (id=<optimized out>, buf_pool=<optimized out>) at /ssd/QA-16274-5.5-3/Percona-Server-5.5.28-rel29.3/storage/innobase/buf/buf0lru.c:668
#8 buf_LRU_flush_or_remove_pages (id=id@entry=22999, buf_remove=buf_remove@entry=BUF_REMOVE_FLUSH_NO_WRITE) at /ssd/QA-16274-5.5-3/Percona-Server-5.5.28-rel29.3/storage/innobase/buf/buf0lru.c:864
#9 0x0000000000935050 in fil_delete_tablespace (id=id@entry=22999, evict_all=0, evict_all@entry=1) at /ssd/QA-16274-5.5-3/Percona-Server-5.5.28-rel29.3/storage/innobase/fil/fil0fil.c:2398
#10 0x0000000000846cbf in row_drop_table_for_mysql (name=0x7f2a18050888 "query02624/#sql2-8bf-5ee", trx=0x7f2a18089738, drop_db=<optimized out>) at /ssd/QA-16274-5.5-3/Percona-Server-5.5.28-rel29.3/storage/innobase/row/row0mysql.c:3577
#11 0x000000000081cdb5 in ha_innobase::delete_table (this=<optimized out>, name=<optimized out>) at /ssd/QA-16274-5.5-3/Percona-Server-5.5.28-rel29.3/storage/innobase/handler/ha_innodb.cc:8452
#12 0x00000000006b9a22 in handler::ha_delete_table (this=this@entry=0x7f2a1804af88, name=name@entry=0x7f2ab610e8a0 "./query02624/#sql2-8bf-5ee") at /ssd/QA-16274-5.5-3/Percona-Server-5.5.28-rel29.3/sql/handler.cc:3660
#13 0x00000000006b9b1b in ha_delete_table (thd=0x39141a0, table_type=<optimized out>, path=0x7f2ab610e8a0 "./query02624/#sql2-8bf-5ee", db=0x7f2a1800d478 "query02624", alias=0x7f2ab610ecc0 "#sql2-8bf-5ee", generate_warning=false) at /ssd/QA-16274-5.5-3/Percona-Server-5.5.28-rel29.3/sql/handler.cc:2211
#14 0x000000000060141b in quick_rm_table (base=base@entry=0x30679b0, db=db@entry=0x7f2a1800d478 "query02624", table_name=table_name@entry=0x7f2ab610ecc0 "#sql2-8bf-5ee", flags=flags@entry=3) at /ssd/QA-16274-5.5-3/Percona-Server-5.5.28-rel29.3/sql/sql_table.cc:2416
#15 0x000000000060ba7a in mysql_alter_table (thd=<optimized out>, new_db=<optimized out>, new_name=0x7f2a1800d490 "t1", create_info=0x7f2ab6110230, table_list=0x7f2a1800d478, alter_info=0x7f2ab6110100, order_num=0, order=0x0, ignore=false) at /ssd/QA-16274-5.5-3/Percona-Server-5.5.28-rel29.3/sql/sql_table.cc:7004
#16 0x00000000007bd089 in Alter_table_statement::execute (this=<optimized out>, thd=0x39141a0) at /ssd/QA-16274-5.5-3/Percona-Server-5.5.28-rel29.3/sql/sql_alter.cc:106
#17 0x00000000005a0b95 in mysql_execute_command (thd=thd@entry=0x39141a0) at /ssd/QA-16274-5.5-3/Percona-Server-5.5.28-rel29.3/sql/sql_parse.cc:4615
#18 0x00000000005a1f2d in mysql_parse (thd=thd@entry=0x39141a0, rawbuf=<optimized out>, length=47, parser_state=parser_state@entry=0x7f2ab6111760) at /ssd/QA-16274-5.5-3/Percona-Server-5.5.28-rel29.3/sql/sql_parse.cc:5844
#19 0x00000000005a2a08 in dispatch_command (command=command@entry=COM_QUERY, thd=thd@entry=0x39141a0, packet=packet@entry=0x39172d1 "ALTER TABLE query02624 . `t1` DROP COLUMN `c30`", packet_length=packet_length@entry=47) at /ssd/QA-16274-5.5-3/Percona-Server-5.5.28-rel29.3/sql/sql_parse.cc:1061
#20 0x00000000005a3fc3 in do_command (thd=0x39141a0) at /ssd/QA-16274-5.5-3/Percona-Server-5.5.28-rel29.3/sql/sql_parse.cc:788
#21 0x000000000064e11c in do_handle_one_connection (thd_arg=thd_arg@entry=0x39141a0) at /ssd/QA-16274-5.5-3/Percona-Server-5.5.28-rel29.3/sql/sql_connect.cc:1497
#22 0x000000000064e212 in handle_one_connection (arg=0x39141a0) at /ssd/QA-16274-5.5-3/Percona-Server-5.5.28-rel29.3/sql/sql_connect.cc:1404
#23 0x0000003da1807d14 in start_thread () from /lib64/libpthread.so.0
#24 0x0000003da14f168d in clone () from /lib64/libc.so.6

========================= Notes:
From Laurynas: Analyzed, it's an easy fix. Looks like one missed case of bug 934377 and friends.

[Laurynas Biveinis (laurynas-biveinis)]

Related: bug 934377, bug 1110102, bug 1111211, bug 1116447.
The fix needs bug 1086680 fix as well (another instance where the new mutex has to be acquired).

[Laurynas Biveinis (laurynas-biveinis)]

This bug needs re-verification, because the lazy drop table feature was removed and a number of other bugs have been fixed. A branch to use for that now is https://code.launchpad.net/~laurynas-biveinis/percona-server/buf-mutex-split-fixes-5.5.

[Roel Van de Paar (roel11)]

See bug 1205502

[Laurynas Biveinis (laurynas-biveinis)]

lp:percona-server/5.5 may be used for re-reverification now.

[Ramesh Sivaraman (rameshvs02)]

Got this issue in PS-5.5.

-------------------------------- GDB.
Thread 1 (Thread 0x7fe8942ae700 (LWP 28020)):
+bt
#0 0x00007fe89a82469c in pthread_kill () from /lib64/libpthread.so.0
#1 0x0000000000803126 in my_write_core (sig=6) at /mnt/workspace/percona-server-5.5-nightly-debug-binaries/label_exp/centos6-64/mysys/stacktrace.c:433
#2 0x00000000006c3c09 in handle_fatal_signal (sig=6) at /mnt/workspace/percona-server-5.5-nightly-debug-binaries/label_exp/centos6-64/sql/signal_handler.cc:250
#3 <signal handler called>
#4 0x00007fe89909d8e5 in raise () from /lib64/libc.so.6
#5 0x00007fe89909f0c5 in abort () from /lib64/libc.so.6
#6 0x00000000008ce8ad in buf_flush_or_remove_pages (buf_pool=0x20218f8, id=4877) at /mnt/workspace/percona-server-5.5-nightly-debug-binaries/label_exp/centos6-64/storage/innobase/buf/buf0lru.c:613
#7 buf_flush_dirty_pages (buf_pool=0x20218f8, id=4877) at /mnt/workspace/percona-server-5.5-nightly-debug-binaries/label_exp/centos6-64/storage/innobase/buf/buf0lru.c:676
#8 0x00000000008d14db in buf_LRU_flush_or_remove_pages (id=4877, buf_remove=BUF_REMOVE_FLUSH_NO_WRITE) at /mnt/workspace/percona-server-5.5-nightly-debug-binaries/label_exp/centos6-64/storage/innobase/buf/buf0lru.c:872
#9 0x0000000000903383 in fil_delete_tablespace (id=4877, evict_all=0) at /mnt/workspace/percona-server-5.5-nightly-debug-binaries/label_exp/centos6-64/storage/innobase/fil/fil0fil.c:2493
#10 0x000000000083be76 in row_drop_table_for_mysql (name=0x7fe83c1038d8 "test/t", trx=<value optimized out>, drop_db=<value optimized out>) at /mnt/workspace/percona-server-5.5-nightly-debug-binaries/label_exp/centos6-64/storage/innobase/row/row0mysql.c:3582
#11 0x0000000000818710 in ha_innobase::delete_table (this=<value optimized out>, name=<value optimized out>) at /mnt/workspace/percona-server-5.5-nightly-debug-binaries/label_exp/centos6-64/storage/innobase/handler/ha_innodb.cc:8535
#12 0x00000000006cbf6a in handler::ha_delete_table (this=0x7fe83c1fa810, name=0x7fe8942ab690 "./test/t") at /mnt/workspace/percona-server-5.5-nightly-debug-binaries/label_exp/centos6-64/sql/handler.cc:3694
#13 0x00000000006cc1c0 in ha_delete_table (thd=0x2529040, table_type=<value optimized out>, path=0x7fe8942ab690 "./test/t", db=0x7fe83c0053d8 "test", alias=0x7fe83c004e78 "t", generate_warning=true) at /mnt/workspace/percona-server-5.5-nightly-debug-binaries/label_exp/centos6-64/sql/handler.cc:2237
#14 0x0000000000612c41 in mysql_rm_table_no_locks (thd=0x2529040, tables=0x7fe83c004eb0, if_exists=true, drop_temporary=false, drop_view=false, dont_log_query=false) at /mnt/workspace/percona-server-5.5-nightly-debug-binaries/label_exp/centos6-64/sql/sql_table.cc:2269
#15 0x0000000000613644 in mysql_rm_table (thd=0x2529040, tables=0x7fe83c004eb0, if_exists=1 '\001', drop_temporary=0 '\000') at /mnt/workspace/percona-server-5.5-nightly-debug-binaries/label_exp/centos6-64/sql/sql_table.cc:1960
#16 0x00000000005a8159 in mysql_execute_command (thd=0x2529040) at /mnt/workspace/percona-server-5.5-nightly-debug-binaries/label_exp/centos6-64/sql/sql_parse.cc:3345
#17 0x00000000005ab71c in mysql_parse (thd=0x2529040, rawbuf=0x7fe83c004dd0 "DROP TABLE IF EXISTS t", length=<value opti...

[Roel Van de Paar (roel11)]

Laurynas, Ramesh added another occurence on 5.5 with full info (ref BUNDLE) - can you check bug again? Thanks.

[Laurynas Biveinis (laurynas-biveinis)]

Thread 31 (Thread 0x7fe880379700 (LWP 27989)):
+bt
#0 0x00007fe89a82343c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x000000000095e366 in os_cond_wait (event=0x23225e0, reset_sig_count=114) at /mnt/workspace/percona-server-5.5-nightly-debug-binaries/label_exp/centos6-64/storage/innobase/os/os0sync.c:207
#2 os_event_wait_low (event=0x23225e0, reset_sig_count=114) at /mnt/workspace/percona-server-5.5-nightly-debug-binaries/label_exp/centos6-64/storage/innobase/os/os0sync.c:609
#3 0x0000000000865158 in sync_array_wait_event (arr=0x1c12e90, index=0) at /mnt/workspace/percona-server-5.5-nightly-debug-binaries/label_exp/centos6-64/storage/innobase/sync/sync0arr.c:458
#4 0x0000000000866bac in mutex_spin_wait (mutex=0x2021ea0, file_name=0xb390f0 "/mnt/workspace/percona-server-5.5-nightly-debug-binaries/label_exp/centos6-64/storage/innobase/buf/buf0flu.c", line=540) at /mnt/workspace/percona-server-5.5-nightly-debug-binaries/label_exp/centos6-64/storage/innobase/sync/sync0sync.c:653
#5 0x00000000008c454b in mutex_enter_func (mutex=0x2021ea0, file_name=0xb390f0 "/mnt/workspace/percona-server-5.5-nightly-debug-binaries/label_exp/centos6-64/storage/innobase/buf/buf0flu.c", line=540) at /mnt/workspace/percona-server-5.5-nightly-debug-binaries/label_exp/centos6-64/storage/innobase/include/sync0sync.ic:222
#6 pfs_mutex_enter_func (mutex=0x2021ea0, file_name=0xb390f0 "/mnt/workspace/percona-server-5.5-nightly-debug-binaries/label_exp/centos6-64/storage/innobase/buf/buf0flu.c", line=540) at /mnt/workspace/percona-server-5.5-nightly-debug-binaries/label_exp/centos6-64/storage/innobase/include/sync0sync.ic:251
#7 0x00000000008c6581 in buf_flush_remove (bpage=0x7fe887fa2100) at /mnt/workspace/percona-server-5.5-nightly-debug-binaries/label_exp/centos6-64/storage/innobase/buf/buf0flu.c:540
#8 0x00000000008c68ad in buf_flush_write_complete (bpage=0x7fe887fa2100) at /mnt/workspace/percona-server-5.5-nightly-debug-binaries/label_exp/centos6-64/storage/innobase/buf/buf0flu.c:676
#9 0x00000000008c42a0 in buf_page_io_complete (bpage=0x7fe887fa2100) at /mnt/workspace/percona-server-5.5-nightly-debug-binaries/label_exp/centos6-64/storage/innobase/buf/buf0buf.c:4110
#10 0x00000000009051f3 in fil_aio_wait (segment=7) at /mnt/workspace/percona-server-5.5-nightly-debug-binaries/label_exp/centos6-64/storage/innobase/fil/fil0fil.c:5719
#11 0x0000000000860b2f in io_handler_thread (arg=<value optimized out>) at /mnt/workspace/percona-server-5.5-nightly-debug-binaries/label_exp/centos6-64/storage/innobase/srv/srv0start.c:489
#12 0x00007fe89a81f851 in start_thread () from /lib64/libpthread.so.0
#13 0x00007fe89915394d in clone () from /lib64/libc.so.6

Thread 19 (Thread 0x7fe875ac4700 (LWP 27998)):
+bt
#0 0x00007fe89a82343c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x000000000095e366 in os_cond_wait (event=0x2022140, reset_sig_count=668) at /mnt/workspace/percona-server-5.5-nightly-debug-binaries/label_exp/centos6-64/storage/innobase/os/os0sync.c:207
#2 os_event_wait_low (event=0x2022140, reset_sig_count=668) at /mnt/workspace/percona-server-5.5-nightly-debug-binaries/label_exp/centos6-64/storage/innobase/os/os0sync.c:...

[Laurynas Biveinis (laurynas-biveinis)]

The buffer page causing assert failure is

$14 = {space = 0, offset = 347, state = 5, flush_type = 2, io_fix = 0, buf_fix_count = 0, buf_pool_index = 0, zip = {data = 0x0, m_start = 0, m_end = 0, m_nonempty = 0, n_blobs = 0, ssize = 0},
  hash = 0x0, in_page_hash = 1, in_zip_hash = 0, free = {prev = 0x7fe887fa5b80, next = 0x0}, flush_list = {prev = 0x7fe887e21500, next = 0x7fe887e18e00}, zip_list = {prev = 0x0, next = 0x0},
  in_flush_list = 0, in_free_list = 0, newest_modification = 237665306, oldest_modification = 0, LRU = {prev = 0x7fe887ff9d00, next = 0x7fe887f613c0}, in_LRU_list = 1, old = 0,
  freed_page_clock = 106800, access_time = 1008817778, is_corrupt = 0, file_page_was_freed = 0}

Besides in_flush_list mismatch there are some other questions (why flush_type = BUF_FLUSH_LIST, in_page_hash = TRUE but both hash table pointers NULL)

All the relevant code places seem to update the flush list presence and in_flush_list flag correctly. I am unable to tell from the stacks at #7 how this crash happened.

Please update if you ever encounter this again.

[Launchpad Janitor (janitor)]

[Expired for Percona Server 5.5 because there has been no activity for 60 days.]

[Launchpad Janitor (janitor)]

[Expired for Percona Server because there has been no activity for 60 days.]

[Launchpad Janitor (janitor)]

[Expired for Percona Server 5.6 because there has been no activity for 60 days.]

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-2890