Percona Server moved to https://jira.percona.com/projects/PS

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

Bug #1122462 reported by Roel Van de Paar
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona Server moved to https://jira.percona.com/projects/PS
Expired
Undecided
Unassigned
5.1
Invalid
Undecided
Unassigned
5.5
Expired
High
Unassigned
5.6
Expired
Undecided
Unassigned

Bug Description

========================= 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.

Tags: qa xtradb

Related branches

lp:~laurynas-biveinis/percona-server/bug1122462
On hold for merging into lp:percona-server/5.5
Laurynas Biveinis (community): Needs Fixing
George Ormond Lorch III (community): Approve (g2)
Diff: 107 lines (+20/-13)
1 file modified
Percona-Server/storage/innobase/buf/buf0lru.c (+20/-13)
Revision history for this message
Roel Van de Paar (roel11) wrote :
Revision history for this message
Roel Van de Paar (roel11) wrote :
Laurynas Biveinis (laurynas-biveinis)
tags: added: xtradb
removed: bitmap
Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

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).

Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

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.

Revision history for this message
Roel Van de Paar (roel11) wrote :

See bug 1205502

Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

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

Roel Van de Paar (roel11)
summary: InnoDB: Failing assertion: bpage->in_flush_list in file buf0lru.c line
- 605
+ 605 | abort in buf_flush_or_remove_pages
Revision history for this message
Ramesh Sivaraman (rameshvs02) wrote :
Download full text (4.4 KiB)

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...

Read more...

Revision history for this message
Roel Van de Paar (roel11) wrote :

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

Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :
Download full text (10.1 KiB)

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:...

Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

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.

Laurynas Biveinis (laurynas-biveinis)
Changed in percona-server:
status: New → Incomplete
Revision history for this message
Launchpad Janitor (janitor) wrote :

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

Revision history for this message
Launchpad Janitor (janitor) wrote :

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

Changed in percona-server:
status: Incomplete → Expired
Revision history for this message
Launchpad Janitor (janitor) wrote :

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

Revision history for this message
Shahriyar Rzayev (rzayev-sehriyar) wrote :

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

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.