dtworkload run failed after enabling PS V3

[JinheLin]

Bug Report

Please answer these questions before submitting your issue. Thanks!

1. Minimal reproduce step (Required)

./tiflash dtworkload --testing_type daily_perf --verify_round 2

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

Run successed.

3. What did you see instead (Required)

libc++abi: terminating with uncaught exception of type DB::Exception: DB::Exception

4. What is your TiFlash version? (Required)

TiFlash
Release Version: v6.1.0-alpha-133-gd539daad5-dirty
Edition:         Community
Git Commit Hash: d539daad547863450e5ca4eb3c6580eae28e8889
Git Branch:      master
UTC Build Time:  2022-05-09 03:20:34
Enable Features: jemalloc avx avx512 unwind
Profile:         RELWITHDEBINFO

5. Details

This error occurred after the DeltaTree was recreated. Here are some error logs:

[root@172-16-5-85 tmp1]$grep ERROR dt_workload_20220509114218.log 
[2022/05/09 11:44:04.503 +08:00] [ERROR] [WriteBatches.h:69] ["WriteBatches:!!!=========================Modifications in log haven't persisted=========================!!! Stack trace: \n       0x1d082b3\tStackTrace::StackTrace() [tiflash+30442163]\n                \tdbms/src/Common/StackTrace.cpp:23\n       0x778ca7f\tDB::DM::WriteBatches::~WriteBatches()::'lambda'(DB::WriteBatch const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&)::operator()(DB::WriteBatch const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&) const [tiflash+125356671]\n                \tdbms/src/Storages/DeltaMerge/WriteBatches.h:65\n       0x7788f37\tDB::DM::WriteBatches::~WriteBatches() [tiflash+125341495]\n                \tdbms/src/Storages/DeltaMerge/WriteBatches.h:72\n       0x7885e3d\tDB::DM::DeltaValueSpace::flush(DB::DM::DMContext&) [tiflash+126377533]\n                \tdbms/src/Storages/DeltaMerge/Delta/DeltaValueSpace.cpp:207\n       0x77a5e3a\tDB::DM::Segment::flushCache(DB::DM::DMContext&) [tiflash+125460026]\n                \tdbms/src/Storages/DeltaMerge/Segment.cpp:1288\n       0x776dea9\tDB::DM::DeltaMergeStore::checkSegmentUpdate(std::__1::shared_ptr<DB::DM::DMContext> const&, std::__1::shared_ptr<DB::DM::Segment> const&, DB::DM::DeltaMergeStore::ThreadType) [tiflash+125230761]\n                \tdbms/src/Storages/DeltaMerge/DeltaMergeStore.cpp:1300\n       0x77713b3\tDB::DM::DeltaMergeStore::write(DB::Context const&, DB::Settings const&, DB::Block&) [tiflash+125244339]\n                \tdbms/src/Storages/DeltaMerge/DeltaMergeStore.cpp:650\n       0x1e3f1bb\tDB::DM::tests::DTWorkload::write(DB::DM::tests::ThreadStat&) [tiflash+31715771]\n                \tdbms/src/Storages/DeltaMerge/tools/workload/DTWorkload.cpp:163\n       0x1e46106\tvoid* std::__1::__thread_proxy<std::__1::tuple<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct> >, void (DB::DM::tests::DTWorkload::*)(DB::DM::tests::ThreadStat&), DB::DM::tests::DTWorkload*, std::__1::reference_wrapper<DB::DM::tests::ThreadStat> > >(void*) [tiflash+31744262]\n                \trelease-centos7-llvm/env/tiflash-env/sysroot/bin/../include/c++/v1/thread:291\n  0x7fc79308ce63\tstart_thread [libpthread.so.0+28259]\n                \t/root/yuzhao/glibc-2.17/nptl/pthread_create.c:308\n  0x7fc792ba655d\t__clone [libc.so.6+968029]\n                \t/root/yuzhao/glibc-2.17/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:113"] [thread_id=38]
[2022/05/09 11:44:04.503 +08:00] [ERROR] [WriteBatches.h:69] ["WriteBatches:!!!=========================Modifications in log haven't persisted=========================!!! Stack trace: \n       0x1d082b3\tStackTrace::StackTrace() [tiflash+30442163]\n                \tdbms/src/Common/StackTrace.cpp:23\n       0x778ca7f\tDB::DM::WriteBatches::~WriteBatches()::'lambda'(DB::WriteBatch const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&)::operator()(DB::WriteBatch const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&) const [tiflash+125356671]\n                \tdbms/src/Storages/DeltaMerge/WriteBatches.h:65\n       0x7788f37\tDB::DM::WriteBatches::~WriteBatches() [tiflash+125341495]\n                \tdbms/src/Storages/DeltaMerge/WriteBatches.h:72\n       0x7885e3d\tDB::DM::DeltaValueSpace::flush(DB::DM::DMContext&) [tiflash+126377533]\n                \tdbms/src/Storages/DeltaMerge/Delta/DeltaValueSpace.cpp:207\n       0x77a5e3a\tDB::DM::Segment::flushCache(DB::DM::DMContext&) [tiflash+125460026]\n                \tdbms/src/Storages/DeltaMerge/Segment.cpp:1288\n       0x777b591\tDB::DM::DeltaMergeStore::handleBackgroundTask(bool) [tiflash+125285777]\n                \tdbms/src/Storages/DeltaMerge/DeltaMergeStore.cpp:1512\n       0x76b5401\tDB::BackgroundProcessingPool::threadFunction() [tiflash+124474369]\n                \tdbms/src/Storages/BackgroundProcessingPool.cpp:233\n       0x76b5d81\tvoid* std::__1::__thread_proxy<std::__1::tuple<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct> >, DB::BackgroundProcessingPool::BackgroundProcessingPool(int)::$_2> >(void*) [tiflash+124476801]\n                \trelease-centos7-llvm/env/tiflash-env/sysroot/bin/../include/c++/v1/thread:291\n  0x7fc79308ce63\tstart_thread [libpthread.so.0+28259]\n                \t/root/yuzhao/glibc-2.17/nptl/pthread_create.c:308\n  0x7fc792ba655d\t__clone [libc.so.6+968029]\n                \t/root/yuzhao/glibc-2.17/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:113"] [thread_id=5]
[2022/05/09 11:44:04.503 +08:00] [ERROR] [WriteBatches.h:69] ["WriteBatches:!!!=========================Modifications in log haven't persisted=========================!!! Stack trace: \n       0x1d082b3\tStackTrace::StackTrace() [tiflash+30442163]\n                \tdbms/src/Common/StackTrace.cpp:23\n       0x778ca7f\tDB::DM::WriteBatches::~WriteBatches()::'lambda'(DB::WriteBatch const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&)::operator()(DB::WriteBatch const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&) const [tiflash+125356671]\n                \tdbms/src/Storages/DeltaMerge/WriteBatches.h:65\n       0x7788f37\tDB::DM::WriteBatches::~WriteBatches() [tiflash+125341495]\n                \tdbms/src/Storages/DeltaMerge/WriteBatches.h:72\n       0x7885e3d\tDB::DM::DeltaValueSpace::flush(DB::DM::DMContext&) [tiflash+126377533]\n                \tdbms/src/Storages/DeltaMerge/Delta/DeltaValueSpace.cpp:207\n       0x77a5e3a\tDB::DM::Segment::flushCache(DB::DM::DMContext&) [tiflash+125460026]\n                \tdbms/src/Storages/DeltaMerge/Segment.cpp:1288\n       0x776dea9\tDB::DM::DeltaMergeStore::checkSegmentUpdate(std::__1::shared_ptr<DB::DM::DMContext> const&, std::__1::shared_ptr<DB::DM::Segment> const&, DB::DM::DeltaMergeStore::ThreadType) [tiflash+125230761]\n                \tdbms/src/Storages/DeltaMerge/DeltaMergeStore.cpp:1300\n       0x77713b3\tDB::DM::DeltaMergeStore::write(DB::Context const&, DB::Settings const&, DB::Block&) [tiflash+125244339]\n                \tdbms/src/Storages/DeltaMerge/DeltaMergeStore.cpp:650\n       0x1e3f1bb\tDB::DM::tests::DTWorkload::write(DB::DM::tests::ThreadStat&) [tiflash+31715771]\n                \tdbms/src/Storages/DeltaMerge/tools/workload/DTWorkload.cpp:163\n       0x1e46106\tvoid* std::__1::__thread_proxy<std::__1::tuple<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct> >, void (DB::DM::tests::DTWorkload::*)(DB::DM::tests::ThreadStat&), DB::DM::tests::DTWorkload*, std::__1::reference_wrapper<DB::DM::tests::ThreadStat> > >(void*) [tiflash+31744262]\n                \trelease-centos7-llvm/env/tiflash-env/sysroot/bin/../include/c++/v1/thread:291\n  0x7fc79308ce63\tstart_thread [libpthread.so.0+28259]\n                \t/root/yuzhao/glibc-2.17/nptl/pthread_create.c:308\n  0x7fc792ba655d\t__clone [libc.so.6+968029]\n                \t/root/yuzhao/glibc-2.17/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:113"] [thread_id=39]
[2022/05/09 11:44:04.503 +08:00] [ERROR] [WriteBatches.h:69] ["WriteBatches:!!!=========================Modifications in log haven't persisted=========================!!! Stack trace: \n       0x1d082b3\tStackTrace::StackTrace() [tiflash+30442163]\n                \tdbms/src/Common/StackTrace.cpp:23\n       0x778ca7f\tDB::DM::WriteBatches::~WriteBatches()::'lambda'(DB::WriteBatch const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&)::operator()(DB::WriteBatch const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&) const [tiflash+125356671]\n                \tdbms/src/Storages/DeltaMerge/WriteBatches.h:65\n       0x7788f37\tDB::DM::WriteBatches::~WriteBatches() [tiflash+125341495]\n                \tdbms/src/Storages/DeltaMerge/WriteBatches.h:72\n       0x7885e3d\tDB::DM::DeltaValueSpace::flush(DB::DM::DMContext&) [tiflash+126377533]\n                \tdbms/src/Storages/DeltaMerge/Delta/DeltaValueSpace.cpp:207\n       0x77a5e3a\tDB::DM::Segment::flushCache(DB::DM::DMContext&) [tiflash+125460026]\n                \tdbms/src/Storages/DeltaMerge/Segment.cpp:1288\n       0x777b591\tDB::DM::DeltaMergeStore::handleBackgroundTask(bool) [tiflash+125285777]\n                \tdbms/src/Storages/DeltaMerge/DeltaMergeStore.cpp:1512\n       0x76b5401\tDB::BackgroundProcessingPool::threadFunction() [tiflash+124474369]\n                \tdbms/src/Storages/BackgroundProcessingPool.cpp:233\n       0x76b5d81\tvoid* std::__1::__thread_proxy<std::__1::tuple<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct> >, DB::BackgroundProcessingPool::BackgroundProcessingPool(int)::$_2> >(void*) [tiflash+124476801]\n                \trelease-centos7-llvm/env/tiflash-env/sysroot/bin/../include/c++/v1/thread:291\n  0x7fc79308ce63\tstart_thread [libpthread.so.0+28259]\n                \t/root/yuzhao/glibc-2.17/nptl/pthread_create.c:308\n  0x7fc792ba655d\t__clone [libc.so.6+968029]\n                \t/root/yuzhao/glibc-2.17/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:113"] [thread_id=27]
[2022/05/09 11:44:04.503 +08:00] [ERROR] [WriteBatches.h:69] ["WriteBatches:!!!=========================Modifications in log haven't persisted=========================!!! Stack trace: \n       0x1d082b3\tStackTrace::StackTrace() [tiflash+30442163]\n                \tdbms/src/Common/StackTrace.cpp:23\n       0x778ca7f\tDB::DM::WriteBatches::~WriteBatches()::'lambda'(DB::WriteBatch const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&)::operator()(DB::WriteBatch const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&) const [tiflash+125356671]\n                \tdbms/src/Storages/DeltaMerge/WriteBatches.h:65\n       0x7788f37\tDB::DM::WriteBatches::~WriteBatches() [tiflash+125341495]\n                \tdbms/src/Storages/DeltaMerge/WriteBatches.h:72\n       0x7885e3d\tDB::DM::DeltaValueSpace::flush(DB::DM::DMContext&) [tiflash+126377533]\n                \tdbms/src/Storages/DeltaMerge/Delta/DeltaValueSpace.cpp:207\n       0x77a5e3a\tDB::DM::Segment::flushCache(DB::DM::DMContext&) [tiflash+125460026]\n                \tdbms/src/Storages/DeltaMerge/Segment.cpp:1288\n       0x776dea9\tDB::DM::DeltaMergeStore::checkSegmentUpdate(std::__1::shared_ptr<DB::DM::DMContext> const&, std::__1::shared_ptr<DB::DM::Segment> const&, DB::DM::DeltaMergeStore::ThreadType) [tiflash+125230761]\n                \tdbms/src/Storages/DeltaMerge/DeltaMergeStore.cpp:1300\n       0x77713b3\tDB::DM::DeltaMergeStore::write(DB::Context const&, DB::Settings const&, DB::Block&) [tiflash+125244339]\n                \tdbms/src/Storages/DeltaMerge/DeltaMergeStore.cpp:650\n       0x1e3f1bb\tDB::DM::tests::DTWorkload::write(DB::DM::tests::ThreadStat&) [tiflash+31715771]\n                \tdbms/src/Storages/DeltaMerge/tools/workload/DTWorkload.cpp:163\n       0x1e46106\tvoid* std::__1::__thread_proxy<std::__1::tuple<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct> >, void (DB::DM::tests::DTWorkload::*)(DB::DM::tests::ThreadStat&), DB::DM::tests::DTWorkload*, std::__1::reference_wrapper<DB::DM::tests::ThreadStat> > >(void*) [tiflash+31744262]\n                \trelease-centos7-llvm/env/tiflash-env/sysroot/bin/../include/c++/v1/thread:291\n  0x7fc79308ce63\tstart_thread [libpthread.so.0+28259]\n                \t/root/yuzhao/glibc-2.17/nptl/pthread_create.c:308\n  0x7fc792ba655d\t__clone [libc.so.6+968029]\n                \t/root/yuzhao/glibc-2.17/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:113"] [thread_id=40]
[2022/05/09 11:44:04.503 +08:00] [ERROR] [DeltaMergeStore.cpp:1533] ["DeltaMergeStore:workload.normal Task Flush on Segment [1] failed. Error msg: try to create entry version with invalid state [ver=<4116,0>] [entry=PageEntry{file: 2, offset: 0xC678ECD, size: 1565, checksum: 0xA499B1F754953B07}] [state={type:6, create_ver: <2751,0>, is_deleted: true, delete_ver: <2785,0>, ori_page_id: 1.41, being_ref_count: 1, num_entries: 0}]:  [type=0] [page_id=1.51] [ver=<4116,0>] [edit_size=2]"] [thread_id=5]
[2022/05/09 11:44:04.503 +08:00] [ERROR] [DeltaMergeStore.cpp:1533] ["DeltaMergeStore:workload.normal Task Flush on Segment [1] failed. Error msg: try to create entry version with invalid state [ver=<4116,0>] [entry=PageEntry{file: 2, offset: 0xC6794EA, size: 160028, checksum: 0x7E9141C2EB095739}] [state={type:6, create_ver: <2751,0>, is_deleted: true, delete_ver: <2785,0>, ori_page_id: 1.42, being_ref_count: 1, num_entries: 0}]:  [type=0] [page_id=1.52] [ver=<4116,0>] [edit_size=3]"] [thread_id=27]
[2022/05/09 11:44:04.517 +08:00] [ERROR] [Exception.cpp:85] ["exception thrown in DTWorkload::write:Code: 0, e.displayText() = DB::Exception: try to create entry version with invalid state [ver=<4117,0>] [entry=PageEntry{file: 2, offset: 0xC8292F2, size: 160028, checksum: 0x7E9141C2EB095739}] [state={type:6, create_ver: <2751,0>, is_deleted: true, delete_ver: <2761,0>, ori_page_id: 1.50, being_ref_count: 1, num_entries: 0}]:  [type=0] [page_id=1.60] [ver=<4117,0>] [edit_size=6], e.what() = DB::Exception, Stack trace:\n\n\n       0x1d082b3\tStackTrace::StackTrace() [tiflash+30442163]\n                \tdbms/src/Common/StackTrace.cpp:23\n       0x1d058b6\tDB::Exception::Exception(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, int) [tiflash+30431414]\n                \tdbms/src/Common/Exception.h:41\n       0x7a391e0\tDB::PS::V3::VersionedPageEntries::createNewEntry(DB::PS::V3::PageVersionType const&, DB::PS::V3::PageEntryV3 const&) [tiflash+128160224]\n                \tdbms/src/Storages/Page/V3/PageDirectory.cpp:108\n       0x7a3da78\tDB::PS::V3::PageDirectory::apply(DB::PS::V3::PageEntriesEdit&&, std::__1::shared_ptr<DB::WriteLimiter> const&) [tiflash+128178808]\n                \tdbms/src/Storages/Page/V3/PageDirectory.cpp:1045\n       0x7a16547\tDB::PS::V3::PageStorageImpl::writeImpl(DB::WriteBatch&&, std::__1::shared_ptr<DB::WriteLimiter> const&) [tiflash+128017735]\n                \tdbms/src/Storages/Page/V3/PageStorageImpl.cpp:101\n       0x778aa87\tDB::DM::WriteBatches::writeLogAndData() [tiflash+125348487]\n                \tdbms/src/Storages/DeltaMerge/WriteBatches.h:115\n       0x7893cbc\tDB::DM::ColumnFileFlushTask::prepare(DB::DM::WriteBatches&) [tiflash+126434492]\n                \tdbms/src/Storages/DeltaMerge/Delta/ColumnFileFlushTask.cpp:58\n       0x7884d5d\tDB::DM::DeltaValueSpace::flush(DB::DM::DMContext&) [tiflash+126373213]\n                \tdbms/src/Storages/DeltaMerge/Delta/DeltaValueSpace.cpp:173\n       0x77a5e3a\tDB::DM::Segment::flushCache(DB::DM::DMContext&) [tiflash+125460026]\n                \tdbms/src/Storages/DeltaMerge/Segment.cpp:1288\n       0x776dea9\tDB::DM::DeltaMergeStore::checkSegmentUpdate(std::__1::shared_ptr<DB::DM::DMContext> const&, std::__1::shared_ptr<DB::DM::Segment> const&, DB::DM::DeltaMergeStore::ThreadType) [tiflash+125230761]\n                \tdbms/src/Storages/DeltaMerge/DeltaMergeStore.cpp:1300\n       0x77713b3\tDB::DM::DeltaMergeStore::write(DB::Context const&, DB::Settings const&, DB::Block&) [tiflash+125244339]\n                \tdbms/src/Storages/DeltaMerge/DeltaMergeStore.cpp:650\n       0x1e3f1bb\tDB::DM::tests::DTWorkload::write(DB::DM::tests::ThreadStat&) [tiflash+31715771]\n                \tdbms/src/Storages/DeltaMerge/tools/workload/DTWorkload.cpp:163\n       0x1e46106\tvoid* std::__1::__thread_proxy<std::__1::tuple<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct> >, void (DB::DM::tests::DTWorkload::*)(DB::DM::tests::ThreadStat&), DB::DM::tests::DTWorkload*, std::__1::reference_wrapper<DB::DM::tests::ThreadStat> > >(void*) [tiflash+31744262]\n                \trelease-centos7-llvm/env/tiflash-env/sysroot/bin/../include/c++/v1/thread:291\n  0x7fc79308ce63\tstart_thread [libpthread.so.0+28259]\n                \t/root/yuzhao/glibc-2.17/nptl/pthread_create.c:308\n  0x7fc792ba655d\t__clone [libc.so.6+968029]\n                \t/root/yuzhao/glibc-2.17/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:113"] [thread_id=38]

[jiaqizho]

Caused by getMaxId change #4838 . That change will make page id reused after V3 restore.

Already revert that PR in #4845 . Verified this problem has not occurred.