Buffer pool watch sentinel page buf_fix_count race condition | InnoDB: Failing assertion: buf_fix_count > 0 in file buf0buf.cc line 3690 | abort (sig=6) in buf_page_init_for_read

[Laurynas Biveinis]

An one-off occurrence on bp-split branch, testcase innodb_bug56680:

http://jenkins.percona.com/job/percona-server-5.6-param/267/BUILD_TYPE=debug,Host=ubuntu-quantal-64bit/testReport/junit/%28root%29/innodb/innodb_bug56680/

...
2013-09-12 12:15:38 7ff450082700 InnoDB: Assertion failure in thread 140687291459328 in file buf0buf.cc line 3694
InnoDB: Failing assertion: buf_fix_count > 0
...

Which appears to be a race condition on buf_fix_count on a page that is a sentinel for buffer pool watch. How exactly this can happen is not clear to me currently. All the watch sentinel buf_fix_count changes happen under zip_mutex and a corresponding page_hash X lock. Further, buf_page_init_for_read() asserts buf_fix_count > 0 through buf_pool_watch_is_sentinel() at line 3647, thus this should have changed between 3647 and 3694, but the hash is X-latched throughout, even though the zip mutex is only acquired at 3670.

Stacktrace:

Thread 1 (Thread 0x7ff450082700 (LWP 29289)):
#0 __pthread_kill (threadid=<optimized out>, signo=<optimized out>) at ../nptl/sysdeps/unix/sysv/linux/pthread_kill.c:63
#1 0x0000000000adaa61 in my_write_core (sig=6) at /home/jenkins/workspace/percona-server-5.6-param/BUILD_TYPE/debug/Host/ubuntu-quantal-64bit/Percona-Server/mysys/stacktrace.c:422
#2 0x00000000007367a1 in handle_fatal_signal (sig=6) at /home/jenkins/workspace/percona-server-5.6-param/BUILD_TYPE/debug/Host/ubuntu-quantal-64bit/Percona-Server/sql/signal_handler.cc:251
#3 <signal handler called>
#4 0x00007ff453577425 in __GI_raise (sig=<optimized out>) at ../nptl/sysdeps/unix/sysv/linux/raise.c:64
#5 0x00007ff45357ab8b in __GI_abort () at abort.c:91
#6 0x0000000000cddfe0 in buf_page_init_for_read (err=0x7ff45007e25c, mode=132, space=525, zip_size=1024, unzip=0, tablespace_version=75, offset=37) at /home/jenkins/workspace/percona-server-5.6-param/BUILD_TYPE/debug/Host/ubuntu-quantal-64bit/Percona-Server/storage/innobase/buf/buf0buf.cc:3694
#7 0x0000000000cfa619 in buf_read_page_low (err=0x7ff45007e25c, sync=true, mode=132, space=525, zip_size=1024, unzip=0, tablespace_version=75, offset=37, trx=0x7ff4280f2c08) at /home/jenkins/workspace/percona-server-5.6-param/BUILD_TYPE/debug/Host/ubuntu-quantal-64bit/Percona-Server/storage/innobase/buf/buf0rea.cc:167
#8 0x0000000000cfaef8 in buf_read_page (space=525, zip_size=1024, offset=37, trx=0x7ff4280f2c08) at /home/jenkins/workspace/percona-server-5.6-param/BUILD_TYPE/debug/Host/ubuntu-quantal-64bit/Percona-Server/storage/innobase/buf/buf0rea.cc:462
#9 0x0000000000cdb2e5 in buf_page_get_gen (space=525, zip_size=1024, offset=37, rw_latch=3, guess=0x0, mode=10, file=0x10bc558 "/home/jenkins/workspace/percona-server-5.6-param/BUILD_TYPE/debug/Host/ubuntu-quantal-64bit/Percona-Server/storage/innobase/include/btr0pcur.ic", line=518, mtr=0x7ff45007ec00) at /home/jenkins/workspace/percona-server-5.6-param/BUILD_TYPE/debug/Host/ubuntu-quantal-64bit/Percona-Server/storage/innobase/buf/buf0buf.cc:2620
#10 0x0000000000cb7f23 in btr_cur_open_at_index_side_func (from_left=true, index=0x7ff4281223c8, latch_mode=1, cursor=0x7ff4280f75d0, level=0, file=0x10bc558 "/home/jenkins/workspace/percona-server-5.6-param/BUILD_TYPE/debug/Host/ubuntu-quantal-64bit/Percona-Server/storage/innobase/include/btr0pcur.ic", line=518, mtr=0x7ff45007ec00) at /home/jenkins/workspace/percona-server-5.6-param/BUILD_TYPE/debug/Host/ubuntu-quantal-64bit/Percona-Server/storage/innobase/btr/btr0cur.cc:973
#11 0x0000000000c238a9 in btr_pcur_open_at_index_side (from_left=true, index=0x7ff4281223c8, latch_mode=1, pcur=0x7ff4280f75d0, init_pcur=false, level=0, mtr=0x7ff45007ec00) at /home/jenkins/workspace/percona-server-5.6-param/BUILD_TYPE/debug/Host/ubuntu-quantal-64bit/Percona-Server/storage/innobase/include/btr0pcur.ic:518
#12 0x0000000000c2bc1b in row_search_for_mysql (buf=0x7ff4280f49f0 "�\001", mode=1, prebuilt=0x7ff4280f7558, match_mode=0, direction=0) at /home/jenkins/workspace/percona-server-5.6-param/BUILD_TYPE/debug/Host/ubuntu-quantal-64bit/Percona-Server/storage/innobase/row/row0sel.cc:4134
#13 0x0000000000afd5cf in ha_innobase::index_read (this=0x7ff42811ce10, buf=0x7ff4280f49f0 "�\001", key_ptr=0x0, key_len=0, find_flag=HA_READ_AFTER_KEY) at /home/jenkins/workspace/percona-server-5.6-param/BUILD_TYPE/debug/Host/ubuntu-quantal-64bit/Percona-Server/storage/innobase/handler/ha_innodb.cc:7867
#14 0x0000000000afe5da in ha_innobase::index_first (this=0x7ff42811ce10, buf=0x7ff4280f49f0 "�\001") at /home/jenkins/workspace/percona-server-5.6-param/BUILD_TYPE/debug/Host/ubuntu-quantal-64bit/Percona-Server/storage/innobase/handler/ha_innodb.cc:8264
#15 0x0000000000645e8a in handler::ha_index_first (this=0x7ff42811ce10, buf=0x7ff4280f49f0 "�\001") at /home/jenkins/workspace/percona-server-5.6-param/BUILD_TYPE/debug/Host/ubuntu-quantal-64bit/Percona-Server/sql/handler.cc:2867
#16 0x00000000007c0e20 in join_read_first (tab=0x7ff4280066e8) at /home/jenkins/workspace/percona-server-5.6-param/BUILD_TYPE/debug/Host/ubuntu-quantal-64bit/Percona-Server/sql/sql_executor.cc:2529
#17 0x00000000007bdfd7 in sub_select (join=0x7ff428005a08, join_tab=0x7ff4280066e8, end_of_records=false) at /home/jenkins/workspace/percona-server-5.6-param/BUILD_TYPE/debug/Host/ubuntu-quantal-64bit/Percona-Server/sql/sql_executor.cc:1253
#18 0x00000000007bd9c1 in do_select (join=0x7ff428005a08) at /home/jenkins/workspace/percona-server-5.6-param/BUILD_TYPE/debug/Host/ubuntu-quantal-64bit/Percona-Server/sql/sql_executor.cc:930
#19 0x00000000007bb89a in JOIN::exec (this=0x7ff428005a08) at /home/jenkins/workspace/percona-server-5.6-param/BUILD_TYPE/debug/Host/ubuntu-quantal-64bit/Percona-Server/sql/sql_executor.cc:191
#20 0x0000000000820426 in mysql_execute_select (thd=0x34e8b90, select_lex=0x34eb768, free_join=true) at /home/jenkins/workspace/percona-server-5.6-param/BUILD_TYPE/debug/Host/ubuntu-quantal-64bit/Percona-Server/sql/sql_select.cc:1101
#21 0x0000000000820728 in mysql_select (thd=0x34e8b90, tables=0x7ff4280053b8, wild_num=0, fields=..., conds=0x0, order=0x34eb930, group=0x34eb868, having=0x0, select_options=2147748608, result=0x7ff4280059e0, unit=0x34eb120, select_lex=0x34eb768) at /home/jenkins/workspace/percona-server-5.6-param/BUILD_TYPE/debug/Host/ubuntu-quantal-64bit/Percona-Server/sql/sql_select.cc:1222
#22 0x000000000081e596 in handle_select (thd=0x34e8b90, result=0x7ff4280059e0, setup_tables_done_option=0) at /home/jenkins/workspace/percona-server-5.6-param/BUILD_TYPE/debug/Host/ubuntu-quantal-64bit/Percona-Server/sql/sql_select.cc:111
#23 0x00000000007f601c in execute_sqlcom_select (thd=0x34e8b90, all_tables=0x7ff4280053b8) at /home/jenkins/workspace/percona-server-5.6-param/BUILD_TYPE/debug/Host/ubuntu-quantal-64bit/Percona-Server/sql/sql_parse.cc:5305
#24 0x00000000007ee562 in mysql_execute_command (thd=0x34e8b90) at /home/jenkins/workspace/percona-server-5.6-param/BUILD_TYPE/debug/Host/ubuntu-quantal-64bit/Percona-Server/sql/sql_parse.cc:2762
#25 0x00000000007f88da in mysql_parse (thd=0x34e8b90, rawbuf=0x7ff428005030 "SELECT HEX(b) FROM bug56680_2 LIMIT 3", length=37, parser_state=0x7ff450080e50) at /home/jenkins/workspace/percona-server-5.6-param/BUILD_TYPE/debug/Host/ubuntu-quantal-64bit/Percona-Server/sql/sql_parse.cc:6477
#26 0x00000000007eb18b in dispatch_command (command=COM_QUERY, thd=0x34e8b90, packet=0x35c2fd1 "", packet_length=37) at /home/jenkins/workspace/percona-server-5.6-param/BUILD_TYPE/debug/Host/ubuntu-quantal-64bit/Percona-Server/sql/sql_parse.cc:1355
#27 0x00000000007ea1b8 in do_command (thd=0x34e8b90) at /home/jenkins/workspace/percona-server-5.6-param/BUILD_TYPE/debug/Host/ubuntu-quantal-64bit/Percona-Server/sql/sql_parse.cc:1049
#28 0x00000000007b0f1a in do_handle_one_connection (thd_arg=0x34e8b90) at /home/jenkins/workspace/percona-server-5.6-param/BUILD_TYPE/debug/Host/ubuntu-quantal-64bit/Percona-Server/sql/sql_connect.cc:1615
#29 0x00000000007b09e8 in handle_one_connection (arg=0x34e8b90) at /home/jenkins/workspace/percona-server-5.6-param/BUILD_TYPE/debug/Host/ubuntu-quantal-64bit/Percona-Server/sql/sql_connect.cc:1526
#30 0x0000000000de7205 in pfs_spawn_thread (arg=0x340df50) at /home/jenkins/workspace/percona-server-5.6-param/BUILD_TYPE/debug/Host/ubuntu-quantal-64bit/Percona-Server/storage/perfschema/pfs.cc:1858
#31 0x00007ff45411ce9a in start_thread (arg=0x7ff450082700) at pthread_create.c:308
#32 0x00007ff453634ccd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:112
#33 0x0000000000000000 in ?? ()

[Roel Van de Paar (roel11)]

Not 56qual because of bug 1217158 which looks like the 5.5 version of this bug?

[Roel Van de Paar (roel11)]

Bug seen in 5.6.13-rc60.5-454-debug (5.6-QA tree) @ RQG 926 <email address hidden>

[Laurynas Biveinis (laurynas-biveinis)]

No relation to bug 1217158.

[Laurynas Biveinis (laurynas-biveinis)]

The issue is missing watch_page recheck in buf_page_init_for_read() after the mutex re-acquisition. There is an re-check already "if (UNIV_UNLIKELY(lru))", but it was not adjusted for the buffer pool mutex split: stock released buffer pool mutex some of the time, we release the LRU list mutex in its place all the time.

[Laurynas Biveinis (laurynas-biveinis)]

The bug is not present in 5.1 or 5.5.

[Shahriyar Rzayev (rzayev-sehriyar)]

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