|
The bug was found during work on MDEV-24719 during testing the branch bb-10.2-MDEV-24719-last-skipped-lsn-check.
rr traces can be found here: pluto:/data/Results/1614023765/TBR-900/dev/shm/vardir/1614023765/22/1/rr
mysqld.1 fails with the following stack trace:
#0 recv_recover_page (block=0x51ac25e513c0, mtr=..., recv_addr=0x51ac2690e388, init_lsn=0) at /Server/bb-10.2-MDEV-24719-last-skipped-lsn-checkA/storage/innobase/log/log0recv.cc:2127
|
#1 0x00005592bd07268c in recv_recover_page (bpage=0x51ac25e513c0) at /Server/bb-10.2-MDEV-24719-last-skipped-lsn-checkA/storage/innobase/log/log0recv.cc:2295
|
#2 0x00005592bd45cfd9 in buf_page_io_complete (bpage=0x51ac25e513c0, dblwr=true, evict=false) at /Server/bb-10.2-MDEV-24719-last-skipped-lsn-checkA/storage/innobase/buf/buf0buf.cc:6123
|
when
page_lsn = 34402069,
end_lsn = 34265464
recv_addr = {state = RECV_BEING_PROCESSED, space = 6, page_no = 269, ...}
recv = {type = MLOG_COMP_REC_INSERT, ... , start_lsn = 34404511, end_lsn = 34404590, ...}
previous recv = {type = MLOG_ZIP_WRITE_BLOB_PTR, ... , start_lsn = 34265435, end_lsn = 34265464, ...}
To catch it in mysqld.0 we can set the following breakpoint:
b buf_flush_note_modification if end_lsn == 34402069
|
Then take a look what mtr is it and follow records written within this mtr since it's started. After the mtr is started the page
{space = 6, page_no = 269}
is marked as modified for this mtr with the following stack trace:
Thread 22 hit Breakpoint 11, mlog_open (mtr=0x78e025e6f5c0, size=305) at /Server/bb-10.2-MDEV-24719-last-skipped-lsn-checkA/storage/innobase/include/mtr0log.ic:43
|
43 mtr->set_modified();
|
(rr) bt
|
#0 mlog_open (mtr=0x78e025e6f5c0, size=305) at /Server/bb-10.2-MDEV-24719-last-skipped-lsn-checkA/storage/innobase/include/mtr0log.ic:43
|
#1 0x000056265973f098 in mlog_open_and_write_index (mtr=0x78e025e6f5c0, rec=0x7f0626434f01 "\200", index=0x618000120108, type=MLOG_COMP_REC_INSERT, size=274)
|
at /Server/bb-10.2-MDEV-24719-last-skipped-lsn-checkA/storage/innobase/mtr/mtr0log.cc:463
|
#2 0x000056265977af6d in page_cur_insert_rec_write_log (insert_rec=0x7f0626434f01 "\200", rec_size=64, cursor_rec=0x7f0626434063 "infimum", index=0x618000120108, mtr=0x78e025e6f5c0)
|
at /Server/bb-10.2-MDEV-24719-last-skipped-lsn-checkA/storage/innobase/page/page0cur.cc:895
|
#3 0x000056265977d9ec in page_cur_insert_rec_low (current_rec=0x7f0626434063 "infimum", index=0x618000120108, rec=0x7f0626540141 "\200", offsets=0x78e025e6dfa0, mtr=0x78e025e6f5c0)
|
at /Server/bb-10.2-MDEV-24719-last-skipped-lsn-checkA/storage/innobase/page/page0cur.cc:1458
|
#4 0x00005626597889b5 in page_copy_rec_list_end_no_locks (new_block=0x7f0624d25770, block=0x7f0624d3e110, rec=0x7f0626540063 "infimum", index=0x618000120108, mtr=0x78e025e6f5c0)
|
at /Server/bb-10.2-MDEV-24719-last-skipped-lsn-checkA/storage/innobase/page/page0page.cc:574
|
#5 0x00005626597891da in page_copy_rec_list_end (new_block=0x7f0624d25770, block=0x7f0624d3e110, rec=0x7f0626540063 "infimum", index=0x618000120108, mtr=0x78e025e6f5c0)
|
at /Server/bb-10.2-MDEV-24719-last-skipped-lsn-checkA/storage/innobase/page/page0page.cc:669
|
#6 0x0000562659a5f41e in btr_compress (cursor=0x61a000002bb0, adjust=0, mtr=0x78e025e6f5c0) at /Server/bb-10.2-MDEV-24719-last-skipped-lsn-checkA/storage/innobase/btr/btr0btr.cc:3777
|
#7 0x0000562659a9e142 in btr_cur_compress_if_useful (cursor=0x61a000002bb0, adjust=0, mtr=0x78e025e6f5c0) at /Server/bb-10.2-MDEV-24719-last-skipped-lsn-checkA/storage/innobase/btr/btr0cur.cc:5132
|
#8 0x0000562659a9f9df in btr_cur_pessimistic_delete (err=0x78e025e6f2b0, has_reserved_extents=0, cursor=0x61a000002bb0, flags=0, rollback=false, mtr=0x78e025e6f5c0)
|
at /Server/bb-10.2-MDEV-24719-last-skipped-lsn-checkA/storage/innobase/btr/btr0cur.cc:5454
|
#9 0x00005626598b419f in row_purge_remove_clust_if_poss_low (node=0x61a000002b08, mode=65569) at /Server/bb-10.2-MDEV-24719-last-skipped-lsn-checkA/storage/innobase/row/row0purge.cc:149
|
#10 0x00005626598b445e in row_purge_remove_clust_if_poss (node=0x61a000002b08) at /Server/bb-10.2-MDEV-24719-last-skipped-lsn-checkA/storage/innobase/row/row0purge.cc:198
|
#11 0x00005626598b6e10 in row_purge_del_mark (node=0x61a000002b08) at /Server/bb-10.2-MDEV-24719-last-skipped-lsn-checkA/storage/innobase/row/row0purge.cc:781
|
#12 0x00005626598b8cfd in row_purge_record_func (node=0x61a000002b08, undo_rec=0x613000000d20 "", thr=0x616000006de8, updated_extern=false)
|
at /Server/bb-10.2-MDEV-24719-last-skipped-lsn-checkA/storage/innobase/row/row0purge.cc:1100
|
#13 0x00005626598b928c in row_purge (node=0x61a000002b08, undo_rec=0x613000000d20 "", thr=0x616000006de8) at /Server/bb-10.2-MDEV-24719-last-skipped-lsn-checkA/storage/innobase/row/row0purge.cc:1160
|
but the record is not written because log mode is set to MTR_LOG_NONE:
rec_t*
|
page_copy_rec_list_end(
|
/*===================*/
|
buf_block_t* new_block, /*!< in/out: index page to copy to */
|
buf_block_t* block, /*!< in: index page containing rec */
|
rec_t* rec, /*!< in: record on page */
|
dict_index_t* index, /*!< in: record descriptor */
|
mtr_t* mtr) /*!< in: mtr */
|
{
|
page_t* new_page = buf_block_get_frame(new_block);
|
page_zip_des_t* new_page_zip = buf_block_get_page_zip(new_block);
|
...
|
if (new_page_zip) {
|
log_mode = mtr_set_log_mode(mtr, MTR_LOG_NONE);
|
}
|
if (page_dir_get_n_heap(new_page) == PAGE_HEAP_NO_USER_LOW) {
|
...
|
} else {
|
if (dict_index_is_spatial(index)) {
|
...
|
} else {
|
page_copy_rec_list_end_no_locks(new_block, block, rec,
|
index, mtr);
|
}
|
}
|
...
|
}
|
It was done intentionally because it's supposed that for compressed row format redo log record will be written latter when page is compressed:
rec_t*
|
page_copy_rec_list_end(...)
|
{
|
...
|
if (new_page_zip) {
|
mtr_set_log_mode(mtr, log_mode);
|
|
if (!page_zip_compress(new_page_zip,
|
new_page,
|
index,
|
page_zip_level,
|
NULL, mtr)) {
|
...
|
if (!page_zip_reorganize(new_block, index, mtr)) {
|
|
if (!page_zip_decompress(new_page_zip,
|
new_page, FALSE)) {
|
ut_error;
|
}
|
...
|
return(NULL);
|
} else {
|
...
|
}
|
}
|
}
|
...
|
}
|
but no records are written because both page_zip_compress() and page_zip_reorganize() return false because "err = deflate(&c_stream, Z_FINISH);" returns Z_OK instead of expected Z_STREAM_END in page_zip_compress(), i.e. page can not be compressed due to zip overflow.
In this case new_block->frame is returned to initial state with page_zip_decompress() in page_copy_rec_list_end(), and page_copy_rec_list_end() returns NULL, so there is no need to write any redo logs there.
The real problem is that page is marked as modified even if log mode is MTR_LOG_NONE. It's fixed in bb-10.2-MDEV-24719-last-skipped-lsn-check.
The bug can be closed as it's not a bug.
|