[MDEV-23452] Assertion `buf_page_get_io_fix(bpage) == BUF_IO_NONE' failed in buf_page_set_sticky Created: 2020-08-11  Updated: 2021-10-08  Resolved: 2020-08-20

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.2, 10.3, 10.4
Fix Version/s: 10.2.35, 10.3.26, 10.4.16, 10.5.7

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Thirunarayanan Balathandayuthapani
Resolution: Fixed Votes: 0
Labels: rr-profile

Issue Links:
Blocks
Problem/Incident
is caused by MDEV-22456 Dropping the adaptive hash index may ... Closed
is caused by MDEV-23233 Race condition for btr_search_drop_pa... Closed
Relates
relates to MDEV-23456 fil_space_crypt_t::write_page0() is a... Closed
relates to MDEV-23835 InnoDB: Failing assertion: bpage->buf... Open
relates to MDEV-24188 Hang in buf_page_create() after reusi... Closed
relates to MDEV-23693 Failing assertion: my_atomic_load32_e... Closed

 Description   

10.3 863e28ff3e

 
mysqld: /home/mariadb/sticky/10.3/storage/innobase/include/buf0buf.ic:569: void buf_page_set_sticky(buf_page_t*): Assertion `buf_page_get_io_fix(bpage) == BUF_IO_NONE' failed.
 
200811 19:20:19 [ERROR] mysqld got signal 6 ;
 
 
 
#3  0x00007f4dc17634a2 in __GI___assert_fail (assertion=0x558462877270 "buf_page_get_io_fix(bpage) == BUF_IO_NONE", 
    file=0x558462876eb8 "/home/mariadb/sticky/10.3/storage/innobase/include/buf0buf.ic", line=569, 
    function=0x55846287dce0 <buf_page_set_sticky(buf_page_t*)::__PRETTY_FUNCTION__> "void buf_page_set_sticky(buf_page_t*)") at assert.c:101
 
#4  0x00005584621b068f in buf_page_set_sticky (bpage=0x7f4da3afe610) at /home/mariadb/sticky/10.3/storage/innobase/include/buf0buf.ic:569
 
#5  0x00005584621c5f3b in buf_page_create (page_id=..., page_size=..., mtr=0x7f4d800aaf60) at /home/mariadb/sticky/10.3/storage/innobase/buf/buf0buf.cc:5656
 
#6  0x00005584622803d1 in fsp_page_create (space=0x558465705200, offset=509, page_size=..., rw_latch=RW_X_LATCH, mtr=0x7f4d800aaf60, init_mtr=0x7f4d800aaf60)
 
    at /home/mariadb/sticky/10.3/storage/innobase/fsp/fsp0fsp.cc:1190
 
#7  0x0000558462280bbd in fsp_alloc_free_page (space=0x558465705200, page_size=..., hint=507, rw_latch=RW_X_LATCH, mtr=0x7f4d800aaf60, init_mtr=0x7f4d800aaf60)
 
    at /home/mariadb/sticky/10.3/storage/innobase/fsp/fsp0fsp.cc:1337
 
#8  0x0000558462284b75 in fseg_alloc_free_page_low (space=0x558465705200, page_size=..., seg_inode=0x7f4da4903e72 "", hint=507, direction=111 'o', rw_latch=RW_X_LATCH, 
    mtr=0x7f4d800aaf60, init_mtr=0x7f4d800aaf60, has_done_reservation=1) at /home/mariadb/sticky/10.3/storage/innobase/fsp/fsp0fsp.cc:2379
 
#9  0x0000558462285491 in fseg_alloc_free_page_general (seg_header=0x7f4da4f5c03c "", hint=507, direction=111 'o', has_done_reservation=1, mtr=0x7f4d800aaf60, init_mtr=0x7f4d800aaf60)
 
    at /home/mariadb/sticky/10.3/storage/innobase/fsp/fsp0fsp.cc:2515
 
#10 0x0000558462137bfb in trx_undo_add_page (undo=0x7f4d38104c00, mtr=0x7f4d800aaf60) at /home/mariadb/sticky/10.3/storage/innobase/trx/trx0undo.cc:787
 
#11 0x00005584621140ff in trx_undo_report_row_operation (thr=0x7f4d3837f850, index=0x7f4d3440e090, clust_entry=0x7f4d380f0190, update=0x0, cmpl_info=0, rec=0x7f4da4638337 "", 
    offsets=0x7f4d800abaa0, roll_ptr=0x7f4d800ab4a0) at /home/mariadb/sticky/10.3/storage/innobase/trx/trx0rec.cc:2104
 
#12 0x00005584621843dc in btr_cur_del_mark_set_clust_rec (block=0x7f4da3aa5f60, rec=0x7f4da4638337 "", index=0x7f4d3440e090, offsets=0x7f4d800abaa0, thr=0x7f4d3837f850, 
    entry=0x7f4d380f0190, mtr=0x7f4d800abd00) at /home/mariadb/sticky/10.3/storage/innobase/btr/btr0cur.cc:5211
 
#13 0x00005584620badb9 in row_upd_del_mark_clust_rec (node=0x7f4d3837f548, index=0x7f4d3440e090, offsets=0x7f4d800abaa0, thr=0x7f4d3837f850, referenced=0, foreign=false, 
    mtr=0x7f4d800abd00) at /home/mariadb/sticky/10.3/storage/innobase/row/row0upd.cc:3001
 
#14 0x00005584620bb85f in row_upd_clust_step (node=0x7f4d3837f548, thr=0x7f4d3837f850) at /home/mariadb/sticky/10.3/storage/innobase/row/row0upd.cc:3179
 
#15 0x00005584620bbe38 in row_upd (node=0x7f4d3837f548, thr=0x7f4d3837f850) at /home/mariadb/sticky/10.3/storage/innobase/row/row0upd.cc:3308
 
#16 0x00005584620bc406 in row_upd_step (thr=0x7f4d3837f850) at /home/mariadb/sticky/10.3/storage/innobase/row/row0upd.cc:3452
 
#17 0x000055846204dd47 in row_update_for_mysql (prebuilt=0x7f4d3837eaa0) at /home/mariadb/sticky/10.3/storage/innobase/row/row0mysql.cc:1847
 
#18 0x0000558461eb4d83 in ha_innobase::delete_row (this=0x7f4d38209418, record=0x7f4d380feb50 "\371\004") at /home/mariadb/sticky/10.3/storage/innobase/handler/ha_innodb.cc:8909
 
#19 0x0000558461c90850 in handler::ha_delete_row (this=0x7f4d38209418, buf=0x7f4d380feb50 "\371\004") at /home/mariadb/sticky/10.3/sql/handler.cc:6554
 
#20 0x0000558461e38ebb in TABLE::delete_row (this=0x7f4d38647f60) at /home/mariadb/sticky/10.3/sql/sql_delete.cc:245
 
#21 0x0000558461e35fd9 in mysql_delete (thd=0x7f4d38000d50, table_list=0x7f4d38011920, conds=0x0, order_list=0x7f4d38005618, limit=18446744073709551415, options=549755813888, 
    result=0x0) at /home/mariadb/sticky/10.3/sql/sql_delete.cc:720
 
#22 0x00005584619648d3 in mysql_execute_command (thd=0x7f4d38000d50) at /home/mariadb/sticky/10.3/sql/sql_parse.cc:4649
 
#23 0x000055846196f63a in mysql_parse (thd=0x7f4d38000d50, rawbuf=0x7f4d380117b8 "DELETE /* QNO 4357 CON_ID 15 */ FROM transforms.insert_select_79412", length=67, 
    parser_state=0x7f4d800ad610, is_com_multi=false, is_next_command=false) at /home/mariadb/sticky/10.3/sql/sql_parse.cc:7810
 
#24 0x000055846195be6f in dispatch_command (command=COM_QUERY, thd=0x7f4d38000d50, packet=0x7f4d386949f1 "DELETE /* QNO 4357 CON_ID 15 */ FROM transforms.insert_select_79412", 
    packet_length=67, is_com_multi=false, is_next_command=false) at /home/mariadb/sticky/10.3/sql/sql_parse.cc:1847
 
#25 0x000055846195a789 in do_command (thd=0x7f4d38000d50) at /home/mariadb/sticky/10.3/sql/sql_parse.cc:1393
 
#26 0x0000558461ad4131 in do_handle_one_connection (connect=0x5584657c7d40) at /home/mariadb/sticky/10.3/sql/sql_connect.cc:1403
 
#27 0x0000558461ad3e93 in handle_one_connection (arg=0x5584657c7d40) at /home/mariadb/sticky/10.3/sql/sql_connect.cc:1308
 
#28 0x00007f4dc246a6db in start_thread (arg=0x7f4d800ae700) at pthread_create.c:463
 
#29 0x00007f4dc1854a3f in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95

The test case which I have for it is very big and unstable, it's not good for debugging, but was sufficient for getting an rr profile.

Observed on 10.2-10.4. I haven't seen it happen on 10.5 so far.
May be related to MDEV-23439.

 Comments   
Comment by Marko Mäkelä [ 2020-08-12 ]

Note: In 10.5, the code is different due to MDEV-15053. It is too early to judge whether 10.5 is affected in some way.

Comment by Thirunarayanan Balathandayuthapani [ 2020-08-12 ]

I analysed the rr-profile and found out that buf_page_create() can get the page with io_fix as BUF_IO_WRITE.
Scenario is that page cleaner thread (thread 2) tries to flush the page by making io_fix as BUF_IO_WRITE
and adds the page to the dblwr buffer. Thread 32 tries to create the same page, fetches exist
block and fails while making the page sticky.

The following information to understand the problem:

Thread 2 hit Breakpoint 2, buf_flush_page (buf_pool=0x558464e4bde0, 
    bpage=0x7f4da3afe610, flush_type=BUF_FLUSH_LIST, sync=false)
 
    at /home/mariadb/sticky/10.3/storage/innobase/buf/buf0flu.cc:1141
 
1141		ut_ad(flush_type < BUF_FLUSH_N_TYPES);
 
(rr) when
 
Current event: 1716224
 
(rr) where
 
#0  buf_flush_page (buf_pool=0x558464e4bde0, bpage=0x7f4da3afe610, 
    flush_type=BUF_FLUSH_LIST, sync=false)
 
    at /home/mariadb/sticky/10.3/storage/innobase/buf/buf0flu.cc:1141
 
#1  0x00005584621de69f in buf_flush_try_neighbors (page_id=..., 
    flush_type=BUF_FLUSH_LIST, n_flushed=3, n_to_flush=6)
 
    at /home/mariadb/sticky/10.3/storage/innobase/buf/buf0flu.cc:1460
 
#2  0x00005584621dea16 in buf_flush_page_and_try_neighbors (
 
    bpage=0x7f4da3b0cf80, flush_type=BUF_FLUSH_LIST, n_to_flush=6, 
    count=0x7f4da235c9b8)
 
    at /home/mariadb/sticky/10.3/storage/innobase/buf/buf0flu.cc:1532
 
#3  0x00005584621df7ff in buf_do_flush_list_batch (buf_pool=0x558464e4bde0, 
    min_n=6, lsn_limit=18446744073709551615)
 
    at /home/mariadb/sticky/10.3/storage/innobase/buf/buf0flu.cc:1791
 
#4  0x00005584621dfe75 in buf_flush_batch (buf_pool=0x558464e4bde0, 
    flush_type=BUF_FLUSH_LIST, min_n=6, lsn_limit=18446744073709551615, 
    n=0x7f4da235cc70)
 
    at /home/mariadb/sticky/10.3/storage/innobase/buf/buf0flu.cc:1861
 
#5  0x00005584621e064a in buf_flush_do_batch (buf_pool=0x558464e4bde0, 
    type=BUF_FLUSH_LIST, min_n=6, lsn_limit=18446744073709551615, 
    n=0x7f4da235cc70)
 
    at /home/mariadb/sticky/10.3/storage/innobase/buf/buf0flu.cc:2019
 
#6  0x00005584621e340d in pc_flush_slot ()
 
    at /home/mariadb/sticky/10.3/storage/innobase/buf/buf0flu.cc:2818
 
#7  0x00005584621e44d7 in buf_flush_page_cleaner_coordinator ()
 
    at /home/mariadb/sticky/10.3/storage/innobase/buf/buf0flu.cc:3231
 
#8  0x00007f4dc246a6db in start_thread (arg=0x7f4da235d700)
 
    at pthread_create.c:463
 
#9  0x00007f4dc1854a3f in clone ()
 
    at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
 
 
 
 
(rr) p bpage->id
 
$2 = {m_space = 0, m_page_no = 509}
 
 
 
 
 
 
 
(rr) t 32
 
[Switching to thread 32 (Thread 50188.50935)]
 
#0  buf_page_create (page_id=..., page_size=..., mtr=0x7f4d800aaf60)
 
    at /home/mariadb/sticky/10.3/storage/innobase/buf/buf0buf.cc:5628
 
5628		buf_block_t*	free_block	= NULL;
 
 
 
 
 
(rr) when
 
Current event: 1716458
 
 
 
#0  buf_page_create (page_id=..., page_size=..., mtr=0x7f4d800aaf60)
 
    at /home/mariadb/sticky/10.3/storage/innobase/buf/buf0buf.cc:5628
 
#1  0x00005584622803d1 in fsp_page_create (space=0x558465705200, offset=509, 
    page_size=..., rw_latch=RW_X_LATCH, mtr=0x7f4d800aaf60, 
    init_mtr=0x7f4d800aaf60)
 
    at /home/mariadb/sticky/10.3/storage/innobase/fsp/fsp0fsp.cc:1190
 
#2  0x0000558462280bbd in fsp_alloc_free_page (space=0x558465705200, 
    page_size=..., hint=507, rw_latch=RW_X_LATCH, mtr=0x7f4d800aaf60, 
    init_mtr=0x7f4d800aaf60)
 
    at /home/mariadb/sticky/10.3/storage/innobase/fsp/fsp0fsp.cc:1337
 
#3  0x0000558462284b75 in fseg_alloc_free_page_low (space=0x558465705200, 
    page_size=..., seg_inode=0x7f4da4903e72 "", hint=507, direction=111 'o', 
    rw_latch=RW_X_LATCH, mtr=0x7f4d800aaf60, init_mtr=0x7f4d800aaf60, 
    has_done_reservation=1)
 
    at /home/mariadb/sticky/10.3/storage/innobase/fsp/fsp0fsp.cc:2379
 
#4  0x0000558462285491 in fseg_alloc_free_page_general (
 
    seg_header=0x7f4da4f5c03c "", hint=507, direction=111 'o', 
    has_done_reservation=1, mtr=0x7f4d800aaf60, init_mtr=0x7f4d800aaf60)
 
    at /home/mariadb/sticky/10.3/storage/innobase/fsp/fsp0fsp.cc:2515
 
#5  0x0000558462137bfb in trx_undo_add_page (undo=0x7f4d38104c00, 
    mtr=0x7f4d800aaf60)
 
    at /home/mariadb/sticky/10.3/storage/innobase/trx/trx0undo.cc:787
 
#6  0x00005584621140ff in trx_undo_report_row_operation (thr=0x7f4d3837f850, 
    index=0x7f4d3440e090, clust_entry=0x7f4d380f0190, update=0x0, 
    cmpl_info=0, rec=0x7f4da4638337 "", offsets=0x7f4d800abaa0, 
    roll_ptr=0x7f4d800ab4a0)
 
    at /home/mariadb/sticky/10.3/storage/innobase/trx/trx0rec.cc:2104
 
#7  0x00005584621843dc in btr_cur_del_mark_set_clust_rec (
 
    block=0x7f4da3aa5f60, rec=0x7f4da4638337 "", index=0x7f4d3440e090, 
    offsets=0x7f4d800abaa0, thr=0x7f4d3837f850, entry=0x7f4d380f0190, 
    mtr=0x7f4d800abd00)
 
    at /home/mariadb/sticky/10.3/storage/innobase/btr/btr0cur.cc:5211
 
#8  0x00005584620badb9 in row_upd_del_mark_clust_rec (node=0x7f4d3837f548, 
    index=0x7f4d3440e090, offsets=0x7f4d800abaa0, thr=0x7f4d3837f850, 
    referenced=0, foreign=false, mtr=0x7f4d800abd00)
 
    at /home/mariadb/sticky/10.3/storage/innobase/row/row0upd.cc:3001
 
#9  0x00005584620bb85f in row_upd_clust_step (node=0x7f4d3837f548, 
    thr=0x7f4d3837f850)
 
    at /home/mariadb/sticky/10.3/storage/innobase/row/row0upd.cc:3179
 
#10 0x00005584620bbe38 in row_upd (node=0x7f4d3837f548, thr=0x7f4d3837f850)
 
    at /home/mariadb/sticky/10.3/storage/innobase/row/row0upd.cc:3308
 
#11 0x00005584620bc406 in row_upd_step (thr=0x7f4d3837f850)
 
---Type <return> to continue, or q <return> to quit---
 
    at /home/mariadb/sticky/10.3/storage/innobase/row/row0upd.cc:3452
 
#12 0x000055846204dd47 in row_update_for_mysql (prebuilt=0x7f4d3837eaa0)
 
    at /home/mariadb/sticky/10.3/storage/innobase/row/row0mysql.cc:1847
 
#13 0x0000558461eb4d83 in ha_innobase::delete_row (this=0x7f4d38209418, 
    record=0x7f4d380feb50 "\371\004")
 
    at /home/mariadb/sticky/10.3/storage/innobase/handler/ha_innodb.cc:8909
 
#14 0x0000558461c90850 in handler::ha_delete_row (this=0x7f4d38209418, 
    buf=0x7f4d380feb50 "\371\004")
 
    at /home/mariadb/sticky/10.3/sql/handler.cc:6554
 
#15 0x0000558461e38ebb in TABLE::delete_row (this=0x7f4d38647f60)
 
    at /home/mariadb/sticky/10.3/sql/sql_delete.cc:245
 
#16 0x0000558461e35fd9 in mysql_delete (thd=0x7f4d38000d50, 
    table_list=0x7f4d38011920, conds=0x0, order_list=0x7f4d38005618, 
    limit=18446744073709551415, options=549755813888, result=0x0)
 
    at /home/mariadb/sticky/10.3/sql/sql_delete.cc:720
 
#17 0x00005584619648d3 in mysql_execute_command (thd=0x7f4d38000d50)
 
    at /home/mariadb/sticky/10.3/sql/sql_parse.cc:4649
 
#18 0x000055846196f63a in mysql_parse (thd=0x7f4d38000d50, 
    rawbuf=0x7f4d380117b8 "DELETE /* QNO 4357 CON_ID 15 */ FROM transforms.insert_select_79412", length=67, parser_state=0x7f4d800ad610, 
    is_com_multi=false, is_next_command=false)
 
    at /home/mariadb/sticky/10.3/sql/sql_parse.cc:7810
 
#19 0x000055846195be6f in dispatch_command (command=COM_QUERY, 
    thd=0x7f4d38000d50, 
    packet=0x7f4d386949f1 "DELETE /* QNO 4357 CON_ID 15 */ FROM transforms.insert_select_79412", packet_length=67, is_com_multi=false, 
    is_next_command=false) at /home/mariadb/sticky/10.3/sql/sql_parse.cc:1847
 
#20 0x000055846195a789 in do_command (thd=0x7f4d38000d50)
 
    at /home/mariadb/sticky/10.3/sql/sql_parse.cc:1393
 
#21 0x0000558461ad4131 in do_handle_one_connection (connect=0x5584657c7d40)
 
    at /home/mariadb/sticky/10.3/sql/sql_connect.cc:1403
 
#22 0x0000558461ad3e93 in handle_one_connection (arg=0x5584657c7d40)
 
    at /home/mariadb/sticky/10.3/sql/sql_connect.cc:1308
 
#23 0x00007f4dc246a6db in start_thread (arg=0x7f4d800ae700)
 
    at pthread_create.c:463
 
#24 0x00007f4dc1854a3f in clone ()
 
    at ../sysdeps/unix/sysv/linux/x86_64/clone.S:95
 
 
 
 
 
 
 
At this moment  t2:
 
#0  0x0000000070000002 in ?? ()
 
#1  0x00007f4dc37ffb27 in _raw_syscall ()
 
    at /home/roc/rr/rr/src/preload/raw_syscall.S:120
 
#2  0x00007f4dc37fae7e in traced_raw_syscall (call=<optimized out>)
 
    at /home/roc/rr/rr/src/preload/syscallbuf.c:229
 
#3  0x00007f4dc37feb55 in syscall_hook_internal (call=0x7f4da1b5cfa0)
 
    at /home/roc/rr/rr/src/preload/syscallbuf.c:2953
 
#4  syscall_hook (call=0x7f4da1b5cfa0)
 
    at /home/roc/rr/rr/src/preload/syscallbuf.c:2987
 
#5  0x00007f4dc37fad5a in _syscall_hook_trampoline ()
 
    at /home/roc/rr/rr/src/preload/syscall_hook.S:282
 
#6  0x00007f4dc37fad8a in __morestack ()
 
    at /home/roc/rr/rr/src/preload/syscall_hook.S:417
 
#7  0x00007f4dc37fada5 in _syscall_hook_trampoline_48_3d_00_f0_ff_ff ()
 
    at /home/roc/rr/rr/src/preload/syscall_hook.S:428
 
#8  0x00007f4dc2474b1d in fsync (fd=7)
 
    at ../sysdeps/unix/sysv/linux/fsync.c:27
 
#9  0x0000558461f97012 in os_file_fsync_posix (file=7)
 
    at /home/mariadb/sticky/10.3/storage/innobase/os/os0file.cc:2518
 
#10 0x0000558461f9736e in os_file_flush_func (file=7)
 
    at /home/mariadb/sticky/10.3/storage/innobase/os/os0file.cc:2611
 
#11 0x000055846225cc7a in pfs_os_file_flush_func (file=..., 
    src_file=0x5584628aa728 "/home/mariadb/sticky/10.3/storage/innobase/fil/fil0fil.cc", src_line=828)
 
    at /home/mariadb/sticky/10.3/storage/innobase/include/os0file.ic:406
 
#12 0x0000558462260370 in fil_flush_low (space=0x558465705200, 
    metadata=false)
 
    at /home/mariadb/sticky/10.3/storage/innobase/fil/fil0fil.cc:828
 
#13 0x000055846226df91 in fil_flush (space_id=0)
 
    at /home/mariadb/sticky/10.3/storage/innobase/fil/fil0fil.cc:4523
 
#14 0x00005584621d32d6 in buf_dblwr_flush_buffered_writes ()
 
    at /home/mariadb/sticky/10.3/storage/innobase/buf/buf0dblwr.cc:1042
 
#15 0x00005584621e0429 in buf_flush_end (buf_pool=0x558464e4bde0, 
    flush_type=BUF_FLUSH_LIST)
 
    at /home/mariadb/sticky/10.3/storage/innobase/buf/buf0flu.cc:1952
 
#16 0x00005584621e065b in buf_flush_do_batch (buf_pool=0x558464e4bde0, 
    type=BUF_FLUSH_LIST, min_n=6, lsn_limit=18446744073709551615, 
    n=0x7f4da235cc70)
 
    at /home/mariadb/sticky/10.3/storage/innobase/buf/buf0flu.cc:2021
 
#17 0x00005584621e340d in pc_flush_slot ()
 
    at /home/mariadb/sticky/10.3/storage/innobase/buf/buf0flu.cc:2818

Comment by Marko Mäkelä [ 2020-08-14 ]

I think that this bug was introduced by MDEV-23233, which fixed a regression due to MDEV-22456.

Comment by Marko Mäkelä [ 2020-08-14 ]

The fix of MDEV-23456 will address this scenario.

Comment by Marko Mäkelä [ 2020-08-20 ]

This fix will be superceded by MDEV-23456 later.

Generated at Thu Feb 08 09:22:31 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.