mysqld: ma_pagecache.c:2103: find_block: Assertion `block->rlocks == 0' failed with Aria on INSERT/REPLACE

[Philip Stoev]

When executing the following RQG workload, Aria asserted as follows within 20 seconds:

mysqld: ma_pagecache.c:2103: find_block: Assertion `block->rlocks == 0' failed.

# 2011-03-02T12:51:24 #5 0x00000035a6e340d5 in abort () from /lib64/libc.so.6
# 2011-03-02T12:51:24 #6 0x00000035a6e2b8b5 in __assert_fail () from /lib64/libc.so.6
# 2011-03-02T12:51:24 #7 0x00000000009d115e in find_block (pagecache=0x1a38b60, file=0x7f4e1000e3e0, pageno=1, init_hits_left=0, wrmode=1 '\001', block_is_c$
# 2011-03-02T12:51:24 reg_req=1 '\001', page_st=0x7f4e8c6d76ec) at ma_pagecache.c:2103
# 2011-03-02T12:51:24 #8 0x00000000009d52a8 in pagecache_read (pagecache=0x1a38b60, file=0x7f4e1000e3e0, pageno=1, level=0, buff=0x0, type=PAGECACHE_LSN_PAG$
# 2011-03-02T12:51:24 lock=PAGECACHE_LOCK_WRITE, page_link=0x7f4e8c6d77f0) at ma_pagecache.c:3383
# 2011-03-02T12:51:24 #9 0x0000000000950543 in get_head_or_tail_page (info=0x7f4e1000dfd8, block=0x7f4e100216a0,
# 2011-03-02T12:51:24 buff=0x7f4e1000e698 "\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\245\2$
# 2011-03-02T12:51:24 page_type=1, lock=PAGECACHE_LOCK_WRITE, res=0x7f4e8c6d78a0) at ma_blockrec.c:1737
# 2011-03-02T12:51:24 #10 0x0000000000955448 in allocate_and_write_block_record (info=0x7f4e1000dfd8, record=0x7f4e100222e0 "\377~", row=0x7f4e1000e038, undo$
# 2011-03-02T12:51:24 at ma_blockrec.c:3494
# 2011-03-02T12:51:24 #11 0x00000000009556e3 in _ma_write_init_block_record (info=0x7f4e1000dfd8, record=0x7f4e100222e0 "\377~") at ma_blockrec.c:3555
# 2011-03-02T12:51:24 #12 0x0000000000996d18 in maria_write (info=0x7f4e1000dfd8, record=0x7f4e100222e0 "\377~") at ma_write.c:146
# 2011-03-02T12:51:24 #13 0x000000000093c246 in ha_maria::write_row (this=0x7f4e10022150, buf=0x7f4e100222e0 "\377~") at ha_maria.cc:1040
# 2011-03-02T12:51:24 #14 0x00000000007cddae in handler::ha_write_row (this=0x7f4e10022150, buf=0x7f4e100222e0 "\377~") at handler.cc:4728
# 2011-03-02T12:51:24 #15 0x000000000072d580 in write_record (thd=0x7f4e10022150, table=0x7f4e100222e0, info=0x93c246) at sql_insert.cc:1405
# 2011-03-02T12:51:24 #16 0x000000000072b4e6 in mysql_insert (thd=0x4b8c928, table_list=0x7f4e14007078, fields=..., values_list=..., update_fields=..., updat$
# 2011-03-02T12:51:24 duplic=DUP_REPLACE, ignore=false) at sql_insert.cc:860
# 2011-03-02T12:51:24 #17 0x000000000068c8df in mysql_execute_command (thd=0x4b8c928) at sql_parse.cc:3279
# 2011-03-02T12:51:24 #18 0x000000000069580d in mysql_parse (thd=0x4b8c928,
# 2011-03-02T12:51:24 rawbuf=0x7f4e14006f10 "REPLACE INTO smf_log_boards (`id_msg`,`id_member`,`id_board`) VALUES (6,126,4832256)", length=84, found_semi$
# 2011-03-02T12:51:24 at sql_parse.cc:6163
# 2011-03-02T12:51:24 #19 0x0000000000687600 in dispatch_command (command=COM_QUERY, thd=0x4b8c928,
# 2011-03-02T12:51:24 packet=0x4b8fbf9 "REPLACE INTO smf_log_boards (`id_msg`,`id_member`,`id_board`) VALUES (6,126,4832256)", packet_length=84) at sql_p$
# 2011-03-02T12:51:24 #20 0x0000000000686620 in do_command (thd=0x4b8c928) at sql_parse.cc:899
# 2011-03-02T12:51:24 #21 0x000000000068360f in handle_one_connection (arg=0x4b8c928) at sql_connect.cc:1151

RQG command line:

perl runall.pl \
--queries=1M \
--engine=Maria \
--mysqld=--default-storage-engine=Maria \
--mysqld=--safe-mode \
--mysqld=--loose-debug-assert-if-crashed-table \
--mysqld=--sync-sys=0 \
--mysqld=--log-output=file \
--mysqld=--maria_log_purge_type=at_flush \
--reporters=ErrorLog,Backtrace,Recovery,Shutdown \
--duration=480 \
--threads=20 \
--rows=10 \
--mask-level=2 \
--mysqld=--loose-maria-group-commit=hard \
--mysqld=--loose-maria_group_commit_interval=0 \
--mysqld=--maria-checkpoint-interval=32K \
--mysqld=--maria-block-size=32K \
--mysqld=--maria-pagecache-buffer-size=512K \
--mysqld=--maria-pagecache-division-limit=75 \
--mysqld=--maria_pagecache_age_threshold=3000 \
--queries=100000000 \
--mask=62144 \
--seed=1299063053 \
--basedir=/home/philips/bzr/maria-5.1-merge/ \
--mysqld=--init-file=/home/philips/bzr/randgen/conf/smf/smf2.sql \
--grammar=conf/smf/smf2.yy

bzr version-info:

revision-id: <email address hidden>
date: 2011-02-25 17:45:53 +0200
build-date: 2011-03-02 18:18:38 +0200
revno: 3043
branch-nick: maria-5.1-merge

[Philip Stoev (pstoev-askmonty)]

Another backtrace:

# 2011-03-03T03:38:29 #5 0x00000035a6e340d5 in abort () from /lib64/libc.so.6
# 2011-03-03T03:38:29 #6 0x00000035a6e2b8b5 in __assert_fail () from /lib64/libc.so.6
# 2011-03-03T03:38:29 #7 0x00000000009d115e in find_block (pagecache=0x1a38b60, file=0x7f095c1291c8, pageno=4, init_hits_left=3, wrmode=1 '\001', block_is_copied=1 '\001',
# 2011-03-03T03:38:29 reg_req=1 '\001', page_st=0x7f09d41ea21c) at ma_pagecache.c:2103
# 2011-03-03T03:38:29 #8 0x00000000009d52a8 in pagecache_read (pagecache=0x1a38b60, file=0x7f095c1291c8, pageno=4, level=3, buff=0x7f09d41ea390 "\001", type=PAGECACHE_LSN_PAGE,
# 2011-03-03T03:38:29 lock=PAGECACHE_LOCK_WRITE, page_link=0x7f09d41ea330) at ma_pagecache.c:3383
# 2011-03-03T03:38:29 #9 0x0000000000993b9c in _ma_fetch_keypage (page=0x7f09d41f2db0, info=0x7f094c069578, keyinfo=0x7f095c129788, pos=131072, lock=PAGECACHE_LOCK_WRITE,
# 2011-03-03T03:38:29 level=3, buff=0x7f09d41ea390 "\001", return_buffer=0 '\000') at ma_page.c:109
# 2011-03-03T03:38:29 #10 0x0000000000998313 in w_search (info=0x7f094c069578, comp_flag=0, key=0x0, page_pos=0, father_page=0x0, father_keypos=0x0, insert_last=0 '\000')
# 2011-03-03T03:38:29 at ma_write.c:619
# 2011-03-03T03:38:29 #11 0x00000000009987b1 in w_search (info=0x7f094c069578, comp_flag=402, key=0x7f09d41f2dc0, page_pos=2815028952344838, father_page=0x7f09d41fc970,
# 2011-03-03T03:38:29 father_keypos=0x20000 <Address 0x20000 out of bounds>, insert_last=9 '\t') at ma_write.c:711
# 2011-03-03T03:38:29 #12 0x0000000000997dd3 in _ma_ck_real_write_btree (info=0x7f094c069578, key=0x7f09d41fc970, root=0x7f09d41fc860, comp_flag=655425) at ma_write.c:512
# 2011-03-03T03:38:29 #13 0x0000000000997c76 in _ma_ck_write_btree_with_log (info=0x7f094c069578, key=0x7f09d41fc970, root=0x7f095c129a38, comp_flag=655425) at ma_write.c:478
# 2011-03-03T03:38:29 #14 0x0000000000997acb in _ma_ck_write_btree (info=0x7f094c069578, key=0x7f09d41fc970) at ma_write.c:438
# 2011-03-03T03:38:29 #15 0x0000000000997a3f in _ma_ck_write (info=0x7f094c069578, key=0x7f09d41fc970) at ma_write.c:423
# 2011-03-03T03:38:29 #16 0x0000000000997247 in maria_write (info=0x7f094c069578, record=0x7f094c05e870 "\377\177\001c") at ma_write.c:178
# 2011-03-03T03:38:29 #17 0x000000000093c246 in ha_maria::write_row (this=0x7f094c05e6e0, buf=0x7f094c05e870 "\377\177\001c") at ha_maria.cc:1040
# 2011-03-03T03:38:29 #18 0x00000000007cddae in handler::ha_write_row (this=0x7f094c05e6e0, buf=0x7f094c05e870 "\377\177\001c") at handler.cc:4728
# 2011-03-03T03:38:29 #19 0x000000000072d64f in write_record (thd=0x7f094c05e6e0, table=0x7f094c05e870, info=0x93c246) at sql_insert.cc:1630
# 2011-03-03T03:38:29 #20 0x000000000072b4e6 in mysql_insert (thd=0x49f1558, table_list=0x7f0958007088, fields=..., values_list=..., update_fields=..., update_values=...,
# 2011-03-03T03:38:29 duplic=DUP_ERROR, ignore=false) at sql_insert.cc:860
# 2011-03-03T03:38:29 #21 0x000000000068c8df in mysql_execute_command (thd=0x49f1558) at sql_parse.cc:3279
# 2011-03-03T03:38:29 #22 0x000000000069580d in mysql_parse (thd=0x49f1558,
# 2011-03-03T03:38:29 rawbuf=0x7f0958006f10 "INSERT INTO smf_permissions (`id_group`,`...

[Michael Widenius (monty)]

Have now run the test case for 36 hours over and over again without any problems, so problem should be fixed.
Fix pushed into 5.2 and merged to 5.3