Percona Server with XtraDB

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

Reported by Laurynas Biveinis on 2013-09-12
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona Server
Status tracked in 5.6
5.1
Undecided
Unassigned
5.5
Undecided
Unassigned
5.6
High
Laurynas Biveinis

Bug Description

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 ?? ()

Changed in percona-server:
assignee: nobody → Laurynas Biveinis (laurynas-biveinis)
status: New → Incomplete
Roel Van de Paar (roel11) wrote :

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

summary: - Buffer pool watch sentinel page buf_fix_count race condition
+ 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
Roel Van de Paar (roel11) wrote :

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

Roel Van de Paar (roel11) wrote :
Roel Van de Paar (roel11) wrote :
Roel Van de Paar (roel11) wrote :
Roel Van de Paar (roel11) wrote :

No relation to bug 1217158.

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.

The bug is not present in 5.1 or 5.5.

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

Other bug subscribers