Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

PageStorage V3 GC can't work when restore #4937

Closed
hehechen opened this issue May 19, 2022 · 1 comment · Fixed by #4938
Closed

PageStorage V3 GC can't work when restore #4937

hehechen opened this issue May 19, 2022 · 1 comment · Fixed by #4938
Assignees
@hehechen
Labels
affects-6.1 This bug affects the 6.1.x(LTS) versions. component/storage severity/critical type/bug The issue is confirmed as a bug.

Comments

@hehechen
Copy link
Contributor

hehechen commented May 19, 2022 •
edited
Loading

Bug Report

Please answer these questions before submitting your issue. Thanks!

1. Minimal reproduce step (Required)

Enable PageStorage V3 in #4884, run the UT:

tiflash/dbms/src/Storages/DeltaMerge/tests/gtest_dm_delta_merge_store.cpp

Line 1417 in 1e1bf1f

TEST_P(DeltaMergeStoreRWTest, Split)

2. What did you expect to see? (Required)

PageStorage V3 GC work successfully and pass all the cases.

3. What did you see instead (Required)

Exception when PageStorage V3 restore.

tiflash/dbms/src/Storages/Page/V3/PageDirectory.cpp

Line 254 in f2513bb

throw Exception(fmt::format(

Because the lowest_seq is 0 when doing loadEdit, so that the gcInMemEntries can't remove the deleted pages.

Here are some logs, we can see that the mvcc gc don't remove the deleted page.

[2022/05/19 23:16:31.712 +08:00] [TRACE] [DeltaMergeStore.cpp:485] ["DeltaMergeStore:test.DeltaMergeStoreRWTest Shutdown DeltaMerge end [test.DeltaMergeStoreRWTest]"] [thread_id=1]
[2022/05/19 23:16:31.712 +08:00] [INFO] [DeltaMergeStore.cpp:286] ["DeltaMergeStore:test.DeltaMergeStoreRWTest Release DeltaMerge Store end [test.DeltaMergeStoreRWTest]"] [thread_id=1]
[2022/05/19 23:16:31.712 +08:00] [TRACE] [DeltaTree.h:935] [DeltaTree:free] [thread_id=1]
[2022/05/19 23:16:31.712 +08:00] [WARN] [Context.cpp:1654] ["Context:GlobalStoragePool has already been initialized."] [thread_id=1]
[2022/05/19 23:16:31.712 +08:00] [INFO] [PageStorageImpl.cpp:41] ["PageStorage:__global__.log PageStorageImpl start. Config{ PageStorage::Config V3 {blob_file_limit_size: 536870912, blob_spacemap_type: 2, blob_cached_fd_size: 100, blob_heavy_gc_valid_rate: 0.200, blob_block_alignment_bytes: 0, wal_roll_size: 2097152, wal_recover_mode: 0, wal_max_persisted_log_files: 4} }"] [thread_id=1]
[2022/05/19 23:16:31.712 +08:00] [INFO] [PageStorageImpl.cpp:41] ["PageStorage:__global__.data PageStorageImpl start. Config{ PageStorage::Config V3 {blob_file_limit_size: 536870912, blob_spacemap_type: 2, blob_cached_fd_size: 100, blob_heavy_gc_valid_rate: 0.200, blob_block_alignment_bytes: 0, wal_roll_size: 2097152, wal_recover_mode: 0, wal_max_persisted_log_files: 4} }"] [thread_id=1]
[2022/05/19 23:16:31.712 +08:00] [INFO] [PageStorageImpl.cpp:41] ["PageStorage:__global__.meta PageStorageImpl start. Config{ PageStorage::Config V3 {blob_file_limit_size: 536870912, blob_spacemap_type: 2, blob_cached_fd_size: 100, blob_heavy_gc_valid_rate: 0.200, blob_block_alignment_bytes: 0, wal_roll_size: 2097152, wal_recover_mode: 0, wal_max_persisted_log_files: 4} }"] [thread_id=1]
[2022/05/19 23:16:31.712 +08:00] [INFO] [BlobStore.cpp:106] ["BlobStore:__global__.log Ignore not blob file [dir=/Users/tonglichen/sourcecode/tics_user/tics/cmake-build-debug/dbms/tmp/TestMode/DeltaMergeStoreRWTest.Split/V1_BlockOnly/page/log] [file=wal] [err_msg=]"] [thread_id=1]
[2022/05/19 23:16:31.712 +08:00] [INFO] [BlobStore.cpp:1214] ["BlobStore:__global__.log Created a new BlobStat [blob_id=1]"] [thread_id=1]
[2022/05/19 23:16:31.712 +08:00] [INFO] [BlobStore.cpp:1214] ["BlobStore:__global__.log Created a new BlobStat [blob_id=3]"] [thread_id=1]
[2022/05/19 23:16:31.712 +08:00] [INFO] [BlobStore.cpp:1214] ["BlobStore:__global__.log Created a new BlobStat [blob_id=2]"] [thread_id=1]
[2022/05/19 23:16:31.712 +08:00] [DEBUG] [WALReader.cpp:205] ["WALStore:__global__.log Open log file for reading [file=/Users/tonglichen/sourcecode/tics_user/tics/cmake-build-debug/dbms/tmp/TestMode/DeltaMergeStoreRWTest.Split/V1_BlockOnly/page/log/wal/log_1_0]"] [thread_id=1]
[2022/05/19 23:16:31.712 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=0] [page_id=101.1] [ver=<1,0>] [entry=PageEntryV3{file: 1, offset: 0x0, size: 123, checksum: 0xAEE82C04581779D1, tag: 0, field_offsets_size: 3}]"] [thread_id=1]
[2022/05/19 23:16:31.713 +08:00] [DEBUG] [WALReader.cpp:205] ["WALStore:__global__.log Open log file for reading [file=/Users/tonglichen/sourcecode/tics_user/tics/cmake-build-debug/dbms/tmp/TestMode/DeltaMergeStoreRWTest.Split/V1_BlockOnly/page/log/wal/log_2_0]"] [thread_id=1]
[2022/05/19 23:16:31.713 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=0] [page_id=101.2] [ver=<2,0>] [entry=PageEntryV3{file: 1, offset: 0x7B, size: 123, checksum: 0xDCAEBAE5F3D6AEA5, tag: 0, field_offsets_size: 3}]"] [thread_id=1]
[2022/05/19 23:16:31.713 +08:00] [DEBUG] [WALReader.cpp:205] ["WALStore:__global__.log Open log file for reading [file=/Users/tonglichen/sourcecode/tics_user/tics/cmake-build-debug/dbms/tmp/TestMode/DeltaMergeStoreRWTest.Split/V1_BlockOnly/page/log/wal/log_3_0]"] [thread_id=1]
[2022/05/19 23:16:31.713 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=0] [page_id=101.3] [ver=<3,0>] [entry=PageEntryV3{file: 1, offset: 0xF6, size: 123, checksum: 0x9AA0427B6B3F17AA, tag: 0, field_offsets_size: 3}]"] [thread_id=1]
[2022/05/19 23:16:31.713 +08:00] [DEBUG] [WALReader.cpp:205] ["WALStore:__global__.log Open log file for reading [file=/Users/tonglichen/sourcecode/tics_user/tics/cmake-build-debug/dbms/tmp/TestMode/DeltaMergeStoreRWTest.Split/V1_BlockOnly/page/log/wal/log_4_0]"] [thread_id=1]
[2022/05/19 23:16:31.713 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=0] [page_id=101.4] [ver=<4,0>] [entry=PageEntryV3{file: 1, offset: 0x171, size: 123, checksum: 0xC36B8B12D61444EE, tag: 0, field_offsets_size: 3}]"] [thread_id=1]
[2022/05/19 23:16:31.713 +08:00] [DEBUG] [WALReader.cpp:205] ["WALStore:__global__.log Open log file for reading [file=/Users/tonglichen/sourcecode/tics_user/tics/cmake-build-debug/dbms/tmp/TestMode/DeltaMergeStoreRWTest.Split/V1_BlockOnly/page/log/wal/log_5_0]"] [thread_id=1]
[2022/05/19 23:16:31.713 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=0] [page_id=101.5] [ver=<5,0>] [entry=PageEntryV3{file: 1, offset: 0x1EC, size: 123, checksum: 0x81DABEE0D70CB931, tag: 0, field_offsets_size: 3}]"] [thread_id=1]
[2022/05/19 23:16:31.713 +08:00] [DEBUG] [WALReader.cpp:205] ["WALStore:__global__.log Open log file for reading [file=/Users/tonglichen/sourcecode/tics_user/tics/cmake-build-debug/dbms/tmp/TestMode/DeltaMergeStoreRWTest.Split/V1_BlockOnly/page/log/wal/log_6_0]"] [thread_id=1]
[2022/05/19 23:16:31.713 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=0] [page_id=101.6] [ver=<6,0>] [entry=PageEntryV3{file: 1, offset: 0x267, size: 123, checksum: 0x217F07D7CE5A2CC2, tag: 0, field_offsets_size: 3}]"] [thread_id=1]
[2022/05/19 23:16:31.713 +08:00] [DEBUG] [WALReader.cpp:205] ["WALStore:__global__.log Open log file for reading [file=/Users/tonglichen/sourcecode/tics_user/tics/cmake-build-debug/dbms/tmp/TestMode/DeltaMergeStoreRWTest.Split/V1_BlockOnly/page/log/wal/log_7_0]"] [thread_id=1]
[2022/05/19 23:16:31.713 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=0] [page_id=101.7] [ver=<7,0>] [entry=PageEntryV3{file: 1, offset: 0x2E2, size: 123, checksum: 0xD7B861D4816A8E87, tag: 0, field_offsets_size: 3}]"] [thread_id=1]
[2022/05/19 23:16:31.713 +08:00] [DEBUG] [WALReader.cpp:205] ["WALStore:__global__.log Open log file for reading [file=/Users/tonglichen/sourcecode/tics_user/tics/cmake-build-debug/dbms/tmp/TestMode/DeltaMergeStoreRWTest.Split/V1_BlockOnly/page/log/wal/log_8_0]"] [thread_id=1]
[2022/05/19 23:16:31.713 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=0] [page_id=101.8] [ver=<8,0>] [entry=PageEntryV3{file: 1, offset: 0x35D, size: 123, checksum: 0x6114A2F52DD6C8D9, tag: 0, field_offsets_size: 3}]"] [thread_id=1]
[2022/05/19 23:16:31.713 +08:00] [DEBUG] [WALReader.cpp:205] ["WALStore:__global__.log Open log file for reading [file=/Users/tonglichen/sourcecode/tics_user/tics/cmake-build-debug/dbms/tmp/TestMode/DeltaMergeStoreRWTest.Split/V1_BlockOnly/page/log/wal/log_9_0]"] [thread_id=1]
[2022/05/19 23:16:31.713 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=0] [page_id=101.9] [ver=<9,0>] [entry=PageEntryV3{file: 1, offset: 0x3D8, size: 123, checksum: 0x58AA666C1EBA37AB, tag: 0, field_offsets_size: 3}]"] [thread_id=1]
[2022/05/19 23:16:31.713 +08:00] [DEBUG] [WALReader.cpp:205] ["WALStore:__global__.log Open log file for reading [file=/Users/tonglichen/sourcecode/tics_user/tics/cmake-build-debug/dbms/tmp/TestMode/DeltaMergeStoreRWTest.Split/V1_BlockOnly/page/log/wal/log_10_0]"] [thread_id=1]
[2022/05/19 23:16:31.713 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=0] [page_id=101.10] [ver=<10,0>] [entry=PageEntryV3{file: 1, offset: 0x453, size: 123, checksum: 0xFACDFA4CA53EFB2B, tag: 0, field_offsets_size: 3}]"] [thread_id=1]
[2022/05/19 23:16:31.713 +08:00] [DEBUG] [WALReader.cpp:205] ["WALStore:__global__.log Open log file for reading [file=/Users/tonglichen/sourcecode/tics_user/tics/cmake-build-debug/dbms/tmp/TestMode/DeltaMergeStoreRWTest.Split/V1_BlockOnly/page/log/wal/log_11_0]"] [thread_id=1]
[2022/05/19 23:16:31.713 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=0] [page_id=101.11] [ver=<11,0>] [entry=PageEntryV3{file: 1, offset: 0x4CE, size: 123, checksum: 0xD466497EF1BCBB20, tag: 0, field_offsets_size: 3}]"] [thread_id=1]
[2022/05/19 23:16:31.713 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=3] [page_id=101.1] [ver=<12,0>] [entry=PageEntryV3{file: 0, offset: 0x0, size: 0, checksum: 0x0, tag: 0, field_offsets_size: 0}]"] [thread_id=1]
[2022/05/19 23:16:31.713 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=3] [page_id=101.2] [ver=<12,0>] [entry=PageEntryV3{file: 0, offset: 0x0, size: 0, checksum: 0x0, tag: 0, field_offsets_size: 0}]"] [thread_id=1]
[2022/05/19 23:16:31.713 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=3] [page_id=101.3] [ver=<12,0>] [entry=PageEntryV3{file: 0, offset: 0x0, size: 0, checksum: 0x0, tag: 0, field_offsets_size: 0}]"] [thread_id=1]
[2022/05/19 23:16:31.713 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=3] [page_id=101.4] [ver=<12,0>] [entry=PageEntryV3{file: 0, offset: 0x0, size: 0, checksum: 0x0, tag: 0, field_offsets_size: 0}]"] [thread_id=1]
[2022/05/19 23:16:31.713 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=3] [page_id=101.5] [ver=<12,0>] [entry=PageEntryV3{file: 0, offset: 0x0, size: 0, checksum: 0x0, tag: 0, field_offsets_size: 0}]"] [thread_id=1]
[2022/05/19 23:16:31.713 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=3] [page_id=101.6] [ver=<12,0>] [entry=PageEntryV3{file: 0, offset: 0x0, size: 0, checksum: 0x0, tag: 0, field_offsets_size: 0}]"] [thread_id=1]
[2022/05/19 23:16:31.713 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=3] [page_id=101.7] [ver=<12,0>] [entry=PageEntryV3{file: 0, offset: 0x0, size: 0, checksum: 0x0, tag: 0, field_offsets_size: 0}]"] [thread_id=1]
[2022/05/19 23:16:31.713 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=3] [page_id=101.8] [ver=<12,0>] [entry=PageEntryV3{file: 0, offset: 0x0, size: 0, checksum: 0x0, tag: 0, field_offsets_size: 0}]"] [thread_id=1]
[2022/05/19 23:16:31.713 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=3] [page_id=101.9] [ver=<12,0>] [entry=PageEntryV3{file: 0, offset: 0x0, size: 0, checksum: 0x0, tag: 0, field_offsets_size: 0}]"] [thread_id=1]
[2022/05/19 23:16:31.713 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=3] [page_id=101.10] [ver=<12,0>] [entry=PageEntryV3{file: 0, offset: 0x0, size: 0, checksum: 0x0, tag: 0, field_offsets_size: 0}]"] [thread_id=1]
[2022/05/19 23:16:31.713 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=3] [page_id=101.11] [ver=<12,0>] [entry=PageEntryV3{file: 0, offset: 0x0, size: 0, checksum: 0x0, tag: 0, field_offsets_size: 0}]"] [thread_id=1]
[2022/05/19 23:16:31.713 +08:00] [DEBUG] [WALReader.cpp:205] ["WALStore:__global__.log Open log file for reading [file=/Users/tonglichen/sourcecode/tics_user/tics/cmake-build-debug/dbms/tmp/TestMode/DeltaMergeStoreRWTest.Split/V1_BlockOnly/page/log/wal/log_12_0]"] [thread_id=1]
[2022/05/19 23:16:31.714 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=0] [page_id=101.1] [ver=<13,0>] [entry=PageEntryV3{file: 2, offset: 0x0, size: 123, checksum: 0xAAAC173BB93C741C, tag: 0, field_offsets_size: 3}]"] [thread_id=1]
[2022/05/19 23:16:31.714 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=3] [page_id=101.1] [ver=<14,0>] [entry=PageEntryV3{file: 0, offset: 0x0, size: 0, checksum: 0x0, tag: 0, field_offsets_size: 0}]"] [thread_id=1]
[2022/05/19 23:16:31.714 +08:00] [DEBUG] [WALReader.cpp:205] ["WALStore:__global__.log Open log file for reading [file=/Users/tonglichen/sourcecode/tics_user/tics/cmake-build-debug/dbms/tmp/TestMode/DeltaMergeStoreRWTest.Split/V1_BlockOnly/page/log/wal/log_13_0]"] [thread_id=1]
[2022/05/19 23:16:31.714 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=0] [page_id=101.1] [ver=<15,0>] [entry=PageEntryV3{file: 3, offset: 0x0, size: 123, checksum: 0xEF35E318DC0A3DF3, tag: 0, field_offsets_size: 3}]"] [thread_id=1]
[2022/05/19 23:16:31.714 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=2] [page_id=101.2] [ver=<16,0>] [entry=PageEntryV3{file: 0, offset: 0x0, size: 0, checksum: 0x0, tag: 0, field_offsets_size: 0}]"] [thread_id=1]
[2022/05/19 23:17:09.795 +08:00] [WARN] [PageDirectoryFactory.cpp:195] ["PageDirectoryFactory:try to resolve error during restore: try to create ref version with invalid state [ver=<16,0>] [ori_page_id=101.1] [state={type:5, create_ver: <0,0>, is_deleted: false, delete_ver: <0,0>, ori_page_id: 0.0, being_ref_count: 1, num_entries: 2}]:  [type=2] [page_id=101.2] [ver=<16,0>]"] [thread_id=1]
[2022/05/19 23:17:19.919 +08:00] [INFO] [PageDirectory.cpp:1372] ["PageDirectory:__global__.log After MVCC gc in memory [lowest_seq=0] clean [invalid_snapshot_nums=0] [invalid_page_nums=0] [total_deref_counter=0] [all_del_entries=0]. Still exist [snapshot_nums=0], [page_nums=11]. Longest alive snapshot: [longest_alive_snapshot_time=0] [longest_alive_snapshot_seq=0] [stale_snapshot_nums=0]"] [thread_id=1]

4. What is your TiFlash version? (Required)

bb572eb
@hehechen hehechen added the type/bug The issue is confirmed as a bug. label May 19, 2022
@hehechen hehechen mentioned this issue May 20, 2022
Merged
12 tasks
@hehechen hehechen self-assigned this May 20, 2022
@flowbehappy flowbehappy added severity/critical affects-6.1 This bug affects the 6.1.x(LTS) versions. labels May 20, 2022
@hehechen
Copy link
Contributor Author

fixed in #4948

ti-chi-bot pushed a commit that referenced this issue May 24, 2022
@hehechen
Revert the retry applyRecord when loadEdit (#4938)
44f0999 
close #4937
@ti-chi-bot ti-chi-bot mentioned this issue May 24, 2022
Merged
12 tasks
ti-chi-bot added a commit that referenced this issue May 24, 2022
@ti-chi-bot
Revert the retry applyRecord when loadEdit (#4938) (#4980)
4094c38 
close #4937
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@hehechen hehechen

Labels
affects-6.1 This bug affects the 6.1.x(LTS) versions. component/storage severity/critical type/bug The issue is confirmed as a bug.
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Revert the retry applyRecord when loadEdit hehechen/tics
4 participants
@zanmato1984 @flowbehappy @hehechen @ti-chi-bot