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 exception #4939

Closed
hehechen opened this issue May 20, 2022 · 2 comments · Fixed by #4948
Closed

PageStorage V3 GC exception #4939

hehechen opened this issue May 20, 2022 · 2 comments · Fixed by #4948
Assignees
@jiaqizho
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

Bug Report

Please answer these questions before submitting your issue. Thanks!

1. Minimal reproduce step (Required)

Enable PageStorage V3 in #4884, run the UT with #4938:

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 GC.

[2022/05/20 08:29:47.510 +08:00] [INFO] [DeltaMergeStore.cpp:286] ["DeltaMergeStore:test.DeltaMergeStoreRWTest Release DeltaMerge Store end [test.DeltaMergeStoreRWTest]"] [thread_id=1]
[2022/05/20 08:29:47.510 +08:00] [TRACE] [DeltaTree.h:935] [DeltaTree:free] [thread_id=1]
[2022/05/20 08:29:47.511 +08:00] [WARN] [Context.cpp:1654] ["Context:GlobalStoragePool has already been initialized."] [thread_id=1]
[2022/05/20 08:29:47.511 +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/20 08:29:47.511 +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/20 08:29:47.511 +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/20 08:29:47.511 +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/V2_Mix/page/log] [file=wal] [err_msg=]"] [thread_id=1]
[2022/05/20 08:29:47.511 +08:00] [INFO] [BlobStore.cpp:1214] ["BlobStore:global.log Created a new BlobStat [blob_id=7]"] [thread_id=1]
[2022/05/20 08:29:47.511 +08:00] [INFO] [BlobStore.cpp:1214] ["BlobStore:global.log Created a new BlobStat [blob_id=8]"] [thread_id=1]
[2022/05/20 08:29:47.511 +08:00] [INFO] [BlobStore.cpp:1214] ["BlobStore:global.log Created a new BlobStat [blob_id=6]"] [thread_id=1]
[2022/05/20 08:29:47.511 +08:00] [INFO] [BlobStore.cpp:1214] ["BlobStore:global.log Created a new BlobStat [blob_id=1]"] [thread_id=1]
[2022/05/20 08:29:47.511 +08:00] [INFO] [BlobStore.cpp:1214] ["BlobStore:global.log Created a new BlobStat [blob_id=4]"] [thread_id=1]
[2022/05/20 08:29:47.511 +08:00] [INFO] [BlobStore.cpp:1214] ["BlobStore:global.log Created a new BlobStat [blob_id=3]"] [thread_id=1]
[2022/05/20 08:29:47.511 +08:00] [INFO] [BlobStore.cpp:1214] ["BlobStore:global.log Created a new BlobStat [blob_id=2]"] [thread_id=1]
[2022/05/20 08:29:47.511 +08:00] [INFO] [BlobStore.cpp:1214] ["BlobStore:global.log Created a new BlobStat [blob_id=5]"] [thread_id=1]
[2022/05/20 08:29:47.511 +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/V2_Mix/page/log/wal/log_1_0]"] [thread_id=1]
[2022/05/20 08:29:47.511 +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: 0xC36B8B12D61444EE, tag: 0, field_offsets_size: 3}]"] [thread_id=1]
[2022/05/20 08:29:47.511 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=3] [page_id=101.1] [ver=<2,0>] [entry=PageEntryV3{file: 0, offset: 0x0, size: 0, checksum: 0x0, tag: 0, field_offsets_size: 0}]"] [thread_id=1]
[2022/05/20 08:29:47.511 +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/V2_Mix/page/log/wal/log_2_0]"] [thread_id=1]
[2022/05/20 08:29:47.511 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=0] [page_id=101.1] [ver=<3,0>] [entry=PageEntryV3{file: 2, offset: 0x0, size: 123, checksum: 0x81DABEE0D70CB931, tag: 0, field_offsets_size: 3}]"] [thread_id=1]
[2022/05/20 08:29:47.511 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=3] [page_id=101.1] [ver=<4,0>] [entry=PageEntryV3{file: 0, offset: 0x0, size: 0, checksum: 0x0, tag: 0, field_offsets_size: 0}]"] [thread_id=1]
[2022/05/20 08:29:47.511 +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/V2_Mix/page/log/wal/log_3_0]"] [thread_id=1]
[2022/05/20 08:29:47.511 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=0] [page_id=101.1] [ver=<5,0>] [entry=PageEntryV3{file: 3, offset: 0x0, size: 123, checksum: 0x217F07D7CE5A2CC2, tag: 0, field_offsets_size: 3}]"] [thread_id=1]
[2022/05/20 08:29:47.511 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=2] [page_id=101.2] [ver=<6,0>] [entry=PageEntryV3{file: 0, offset: 0x0, size: 0, checksum: 0x0, tag: 0, field_offsets_size: 0}]"] [thread_id=1]
[2022/05/20 08:29:47.512 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=3] [page_id=101.1] [ver=<7,0>] [entry=PageEntryV3{file: 0, offset: 0x0, size: 0, checksum: 0x0, tag: 0, field_offsets_size: 0}]"] [thread_id=1]
[2022/05/20 08:29:47.512 +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/V2_Mix/page/log/wal/log_4_0]"] [thread_id=1]
[2022/05/20 08:29:47.512 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=0] [page_id=101.3] [ver=<8,0>] [entry=PageEntryV3{file: 3, offset: 0x7B, size: 123, checksum: 0xD7B861D4816A8E87, tag: 0, field_offsets_size: 3}]"] [thread_id=1]
[2022/05/20 08:29:47.512 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=3] [page_id=101.2] [ver=<9,0>] [entry=PageEntryV3{file: 0, offset: 0x0, size: 0, checksum: 0x0, tag: 0, field_offsets_size: 0}]"] [thread_id=1]
[2022/05/20 08:29:47.512 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=3] [page_id=101.3] [ver=<9,0>] [entry=PageEntryV3{file: 0, offset: 0x0, size: 0, checksum: 0x0, tag: 0, field_offsets_size: 0}]"] [thread_id=1]
[2022/05/20 08:29:47.512 +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/V2_Mix/page/log/wal/log_5_0]"] [thread_id=1]
[2022/05/20 08:29:47.512 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=0] [page_id=101.1] [ver=<10,0>] [entry=PageEntryV3{file: 4, offset: 0x0, size: 123, checksum: 0x6114A2F52DD6C8D9, tag: 0, field_offsets_size: 3}]"] [thread_id=1]
[2022/05/20 08:29:47.512 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=2] [page_id=101.2] [ver=<11,0>] [entry=PageEntryV3{file: 0, offset: 0x0, size: 0, checksum: 0x0, tag: 0, field_offsets_size: 0}]"] [thread_id=1]
[2022/05/20 08:29:47.512 +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/20 08:29:47.512 +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/V2_Mix/page/log/wal/log_6_0]"] [thread_id=1]
[2022/05/20 08:29:47.512 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=0] [page_id=101.3] [ver=<13,0>] [entry=PageEntryV3{file: 4, offset: 0x7B, size: 123, checksum: 0xD466497EF1BCBB20, tag: 0, field_offsets_size: 3}]"] [thread_id=1]
[2022/05/20 08:29:47.512 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=3] [page_id=101.2] [ver=<14,0>] [entry=PageEntryV3{file: 0, offset: 0x0, size: 0, checksum: 0x0, tag: 0, field_offsets_size: 0}]"] [thread_id=1]
[2022/05/20 08:29:47.512 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=3] [page_id=101.3] [ver=<14,0>] [entry=PageEntryV3{file: 0, offset: 0x0, size: 0, checksum: 0x0, tag: 0, field_offsets_size: 0}]"] [thread_id=1]
[2022/05/20 08:29:47.512 +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/V2_Mix/page/log/wal/log_7_0]"] [thread_id=1]
[2022/05/20 08:29:47.512 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=0] [page_id=101.1] [ver=<15,0>] [entry=PageEntryV3{file: 5, offset: 0x0, size: 123, checksum: 0xEF35E318DC0A3DF3, tag: 0, field_offsets_size: 3}]"] [thread_id=1]
[2022/05/20 08:29:47.512 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=3] [page_id=101.1] [ver=<16,0>] [entry=PageEntryV3{file: 0, offset: 0x0, size: 0, checksum: 0x0, tag: 0, field_offsets_size: 0}]"] [thread_id=1]
[2022/05/20 08:29:47.512 +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/V2_Mix/page/log/wal/log_8_0]"] [thread_id=1]
[2022/05/20 08:29:47.512 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=0] [page_id=101.1] [ver=<17,0>] [entry=PageEntryV3{file: 6, offset: 0x0, size: 123, checksum: 0x47642A44337F54AD, tag: 0, field_offsets_size: 3}]"] [thread_id=1]
[2022/05/20 08:29:47.512 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=2] [page_id=101.2] [ver=<18,0>] [entry=PageEntryV3{file: 0, offset: 0x0, size: 0, checksum: 0x0, tag: 0, field_offsets_size: 0}]"] [thread_id=1]
[2022/05/20 08:29:47.512 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=3] [page_id=101.1] [ver=<19,0>] [entry=PageEntryV3{file: 0, offset: 0x0, size: 0, checksum: 0x0, tag: 0, field_offsets_size: 0}]"] [thread_id=1]
[2022/05/20 08:29:47.512 +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/V2_Mix/page/log/wal/log_9_0]"] [thread_id=1]
[2022/05/20 08:29:47.512 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=0] [page_id=101.3] [ver=<20,0>] [entry=PageEntryV3{file: 6, offset: 0x7B, size: 123, checksum: 0xCE8F5EE54BE5624C, tag: 0, field_offsets_size: 3}]"] [thread_id=1]
[2022/05/20 08:29:47.512 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=3] [page_id=101.2] [ver=<21,0>] [entry=PageEntryV3{file: 0, offset: 0x0, size: 0, checksum: 0x0, tag: 0, field_offsets_size: 0}]"] [thread_id=1]
[2022/05/20 08:29:47.512 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=3] [page_id=101.3] [ver=<21,0>] [entry=PageEntryV3{file: 0, offset: 0x0, size: 0, checksum: 0x0, tag: 0, field_offsets_size: 0}]"] [thread_id=1]
[2022/05/20 08:29:47.512 +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/V2_Mix/page/log/wal/log_10_0]"] [thread_id=1]
[2022/05/20 08:29:47.512 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=0] [page_id=101.1] [ver=<22,0>] [entry=PageEntryV3{file: 7, offset: 0x0, size: 123, checksum: 0x87ED35A5812BC3D0, tag: 0, field_offsets_size: 3}]"] [thread_id=1]
[2022/05/20 08:29:47.512 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=3] [page_id=101.1] [ver=<23,0>] [entry=PageEntryV3{file: 0, offset: 0x0, size: 0, checksum: 0x0, tag: 0, field_offsets_size: 0}]"] [thread_id=1]
[2022/05/20 08:29:47.512 +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/V2_Mix/page/log/wal/log_11_0]"] [thread_id=1]
[2022/05/20 08:29:47.512 +08:00] [TRACE] [PageDirectoryFactory.cpp:116] ["PageDirectoryFactory:restoring record [type=0] [page_id=101.1] [ver=<24,0>] [entry=PageEntryV3{file: 8, offset: 0x0, size: 123, checksum: 0x92F22228C38741B3, tag: 0, field_offsets_size: 3}]"] [thread_id=1]
[2022/05/20 08:29:51.746 +08:00] [ERROR] [Exception.cpp:85] ["bool DB::Context::initializeGlobalStoragePoolIfNeed(const DB::PathPool &):Code: 0, e.displayText() = DB::Exception: Can not find entry for decreasing ref count [page_id=101.1] [ver=<18,0>] [deref_count=1], e.what() = DB::Exception, Stack trace:\n\n\n 0x10e7c3a74\tStackTrace::StackTrace() [gtests_dbms+4496947828]\n \tdbms/src/Common/StackTrace.cpp:23\n 0x10e7c3ab0\tStackTrace::StackTrace() [gtests_dbms+4496947888]\n \tdbms/src/Common/StackTrace.cpp:22\n 0x10272fcb4\tDB::Exception::Exception(std::__1::basic_string<char, std::__1::char_traits, std::__1::allocator > const&, int) [gtests_dbms+4295015604]\n \tdbms/src/Common/Exception.h:41\n 0x10272ed2c\tDB::Exception::Exception(std::__1::basic_string<char, std::__1::char_traits, std::__1::allocator > const&, int) [gtests_dbms+4295011628]\n \tdbms/src/Common/Exception.h:43\n 0x10d30e8c4\tDB::PS::V3::VersionedPageEntries::derefAndClean(unsigned long long, DB::UInt128, DB::PS::V3::PageVersion const&, long long, std::__1::vector<DB::PS::V3::PageEntryV3, std::__1::allocatorDB::PS::V3::PageEntryV3 >&) [gtests_dbms+4475234500]\n \tdbms/src/Storages/Page/V3/PageDirectory.cpp:585\n 0x10d316a70\tDB::PS::V3::PageDirectory::gcInMemEntries() [gtests_dbms+4475267696]\n \tdbms/src/Storages/Page/V3/PageDirectory.cpp:1341\n 0x10d33b4d0\tDB::PS::V3::PageDirectoryFactory::create(std::__1::basic_string<char, std::__1::char_traits, std::__1::allocator >, std::__1::shared_ptrDB::FileProvider&, std::__1::shared_ptrDB::PSDiskDelegator&, DB::PS::V3::WALStore::Config) [gtests_dbms+4475417808]\n \tdbms/src/Storages/Page/V3/PageDirectoryFactory.cpp:42\n 0x10d347d38\tDB::PS::V3::PageStorageImpl::restore() [gtests_dbms+4475469112]\n \tdbms/src/Storages/Page/V3/PageStorageImpl.cpp:55\n 0x10cc2f668\tDB::DM::GlobalStoragePool::restore() [gtests_dbms+4468029032]\n \tdbms/src/Storages/DeltaMerge/StoragePool.cpp:120\n 0x10c1a8684\tDB::Context::initializeGlobalStoragePoolIfNeed(DB::PathPool const&) [gtests_dbms+4456990340]\n \tdbms/src/Interpreters/Context.cpp:1662\n 0x104577974\tDB::tests::TiFlashTestEnv::getContext(DB::Settings const&, std::__1::vector<std::__1::basic_string<char, std::__1::char_traits, std::__1::allocator >, std::__1::allocator<std::__1::basic_string<char, std::__1::char_traits, std::__1::allocator > > >) [gtests_dbms+4326766964]\n \tdbms/src/TestUtils/TiFlashTestEnv.cpp:97\n 0x102998b48\tDB::base::TiFlashStorageTestBasic::reload(DB::Settings&&) [gtests_dbms+4297542472]\n \tdbms/src/Storages/tests/TiFlashStorageTestBasic.h:113\n 0x103cfeb9c\tDB::DM::tests::DeltaMergeStoreRWTest::reload(std::__1::shared_ptr<std::__1::vector<DB::DM::ColumnDefine, std::__1::allocatorDB::DM::ColumnDefine > > const&, bool, unsigned long) [gtests_dbms+4317883292]\n \tdbms/src/Storages/DeltaMerge/tests/gtest_dm_delta_merge_store.cpp:165\n 0x103d13a70\tDB::DM::tests::DeltaMergeStoreRWTest_Split_Test::TestBody() [gtests_dbms+4317969008]\n \tdbms/src/Storages/DeltaMerge/tests/gtest_dm_delta_merge_store.cpp:1673\n 0x10a2d907c\tvoid testing::internal::HandleSehExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::)(), char const) [gtests_dbms+4424683644]\n \tcontrib/googletest/googletest/src/gtest.cc:2401\n 0x10a2b1798\tvoid testing::internal::HandleExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::)(), char const) [gtests_dbms+4424521624]\n \tcontrib/googletest/googletest/src/gtest.cc:2437\n 0x10a2b16f4\ttesting::Test::Run() [gtests_dbms+4424521460]\n \tcontrib/googletest/googletest/src/gtest.cc:2473\n 0x10a2b252c\ttesting::TestInfo::Run() [gtests_dbms+4424525100]\n \tcontrib/googletest/googletest/src/gtest.cc:2655\n 0x10a2b3224\ttesting::TestCase::Run() [gtests_dbms+4424528420]\n \tcontrib/googletest/googletest/src/gtest.cc:2773\n 0x10a2b9ce4\ttesting::internal::UnitTestImpl::RunAllTests() [gtests_dbms+4424555748]\n \tcontrib/googletest/googletest/src/gtest.cc:4673\n 0x10a2dde5c\tbool testing::internal::HandleSehExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool>(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::)(), char const) [gtests_dbms+4424703580]\n \tcontrib/googletest/googletest/src/gtest.cc:2401\n 0x10a2b981c\tbool testing::internal::HandleExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool>(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::)(), char const) [gtests_dbms+4424554524]\n \tcontrib/googletest/googletest/src/gtest.cc:2437\n 0x10a2b9714\ttesting::UnitTest::Run() [gtests_dbms+4424554260]\n \tcontrib/googletest/googletest/src/gtest.cc:4281\n 0x104447de0\tRUN_ALL_TESTS() [gtests_dbms+4325522912]\n \tcontrib/googletest/googletest/include/gtest/gtest.h:2237\n 0x104447d14\tmain [gtests_dbms+4325522708]\n \tdbms/src/TestUtils/gtests_dbms_main.cpp:36\n 0x19d8a1430\t [libdyld.dylib+6445634608]"] [thread_id=1]
Code: 0. DB::Exception: Can not find entry for decreasing ref count [page_id=101.1] [ver=<18,0>] [deref_count=1]

Stack trace:

 0x10e7c3a74	StackTrace::StackTrace() [gtests_dbms+4496947828]
            	dbms/src/Common/StackTrace.cpp:23
 0x10e7c3ab0	StackTrace::StackTrace() [gtests_dbms+4496947888]
            	dbms/src/Common/StackTrace.cpp:22
 0x10272fcb4	DB::Exception::Exception(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, int) [gtests_dbms+4295015604]
            	dbms/src/Common/Exception.h:41
 0x10272ed2c	DB::Exception::Exception(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, int) [gtests_dbms+4295011628]
            	dbms/src/Common/Exception.h:43
 0x10d30e8c4	DB::PS::V3::VersionedPageEntries::derefAndClean(unsigned long long, DB::UInt128, DB::PS::V3::PageVersion const&, long long, std::__1::vector<DB::PS::V3::PageEntryV3, std::__1::allocator<DB::PS::V3::PageEntryV3> >&) [gtests_dbms+4475234500]
            	dbms/src/Storages/Page/V3/PageDirectory.cpp:585
 0x10d316a70	DB::PS::V3::PageDirectory::gcInMemEntries() [gtests_dbms+4475267696]
            	dbms/src/Storages/Page/V3/PageDirectory.cpp:1341
 0x10d33b4d0	DB::PS::V3::PageDirectoryFactory::create(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::shared_ptr<DB::FileProvider>&, std::__1::shared_ptr<DB::PSDiskDelegator>&, DB::PS::V3::WALStore::Config) [gtests_dbms+4475417808]
            	dbms/src/Storages/Page/V3/PageDirectoryFactory.cpp:42
 0x10d347d38	DB::PS::V3::PageStorageImpl::restore() [gtests_dbms+4475469112]
            	dbms/src/Storages/Page/V3/PageStorageImpl.cpp:55
 0x10cc2f668	DB::DM::GlobalStoragePool::restore() [gtests_dbms+4468029032]
            	dbms/src/Storages/DeltaMerge/StoragePool.cpp:120
 0x10c1a8684	DB::Context::initializeGlobalStoragePoolIfNeed(DB::PathPool const&) [gtests_dbms+4456990340]
            	dbms/src/Interpreters/Context.cpp:1662
 0x104577974	DB::tests::TiFlashTestEnv::getContext(DB::Settings const&, std::__1::vector<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >, std::__1::allocator<std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > > >) [gtests_dbms+4326766964]
            	dbms/src/TestUtils/TiFlashTestEnv.cpp:97
 0x102998b48	DB::base::TiFlashStorageTestBasic::reload(DB::Settings&&) [gtests_dbms+4297542472]
            	dbms/src/Storages/tests/TiFlashStorageTestBasic.h:113
 0x103cfeb9c	DB::DM::tests::DeltaMergeStoreRWTest::reload(std::__1::shared_ptr<std::__1::vector<DB::DM::ColumnDefine, std::__1::allocator<DB::DM::ColumnDefine> > > const&, bool, unsigned long) [gtests_dbms+4317883292]
            	dbms/src/Storages/DeltaMerge/tests/gtest_dm_delta_merge_store.cpp:165
 0x103d13a70	DB::DM::tests::DeltaMergeStoreRWTest_Split_Test::TestBody() [gtests_dbms+4317969008]
            	dbms/src/Storages/DeltaMerge/tests/gtest_dm_delta_merge_store.cpp:1673
 0x10a2d907c	void testing::internal::HandleSehExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::*)(), char const*) [gtests_dbms+4424683644]
            	contrib/googletest/googletest/src/gtest.cc:2401
 0x10a2b1798	void testing::internal::HandleExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::*)(), char const*) [gtests_dbms+4424521624]
            	contrib/googletest/googletest/src/gtest.cc:2437
 0x10a2b16f4	testing::Test::Run() [gtests_dbms+4424521460]
            	contrib/googletest/googletest/src/gtest.cc:2473
 0x10a2b252c	testing::TestInfo::Run() [gtests_dbms+4424525100]
            	contrib/googletest/googletest/src/gtest.cc:2655
 0x10a2b3224	testing::TestCase::Run() [gtests_dbms+4424528420]
            	contrib/googletest/googletest/src/gtest.cc:2773
 0x10a2b9ce4	testing::internal::UnitTestImpl::RunAllTests() [gtests_dbms+4424555748]
            	contrib/googletest/googletest/src/gtest.cc:4673
 0x10a2dde5c	bool testing::internal::HandleSehExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool>(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::*)(), char const*) [gtests_dbms+4424703580]
            	contrib/googletest/googletest/src/gtest.cc:2401
 0x10a2b981c	bool testing::internal::HandleExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool>(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::*)(), char const*) [gtests_dbms+4424554524]
            	contrib/googletest/googletest/src/gtest.cc:2437
 0x10a2b9714	testing::UnitTest::Run() [gtests_dbms+4424554260]
            	contrib/googletest/googletest/src/gtest.cc:4281
 0x104447de0	RUN_ALL_TESTS() [gtests_dbms+4325522912]
            	contrib/googletest/googletest/include/gtest/gtest.h:2237
 0x104447d14	main [gtests_dbms+4325522708]
            	dbms/src/TestUtils/gtests_dbms_main.cpp:36
 0x19d8a1430	<unknown symbol> [libdyld.dylib+6445634608]

4. What is your TiFlash version? (Required)

bb572eb
@hehechen hehechen added the type/bug The issue is confirmed as a bug. label May 20, 2022
@hehechen
Copy link
Contributor Author

hehechen commented May 20, 2022 •
edited
Loading

  1. put (sequence =17)
  2. ref (sequence =18)
  3. del_ref (sequence =21)
  4. del (sequence =23)
  5. put (sequence =24)

The origin page with sequence less than 23 has been removed from VersionedPageEntries, so can't find it in derefAndClean and throw exception:

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

Line 539 in 1e1bf1f

throw Exception(fmt::format("Can not find entry for decreasing ref count [page_id={}] [ver={}] [deref_count={}]", page_id, deref_ver, deref_count));

@hehechen
Copy link
Contributor Author

log.tar.gz

@jiaqizho jiaqizho mentioned this issue May 20, 2022
Merged
12 tasks
@hehechen hehechen added affects-6.1 This bug affects the 6.1.x(LTS) versions. and removed may-affects-6.1 labels May 20, 2022
@flowbehappy flowbehappy added affects-6.1 This bug affects the 6.1.x(LTS) versions. component/storage and removed affects-6.1 This bug affects the 6.1.x(LTS) versions. labels May 20, 2022
ti-chi-bot pushed a commit that referenced this issue May 23, 2022
@jiaqizho
Add a global max_id to fix reuse page_id problem (#4948)
1dfe7fc 
close #4939
@ti-chi-bot ti-chi-bot mentioned this issue May 23, 2022
Merged
12 tasks
ti-chi-bot added a commit that referenced this issue May 24, 2022
@ti-chi-bot
Add a global max_id to fix reuse page_id problem (#4948) (#4973)
c9fd034 
close #4939
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@jiaqizho jiaqizho

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.

Add a global max_id to fix reuse page_id problem
4 participants
@flowbehappy @jiaqizho @hehechen @ti-chi-bot