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.

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

Error logging when SegmentMerge task is cancelled by segment invalidation #7502

Closed
Tracked by #8673
JaySon-Huang opened this issue May 18, 2023 · 3 comments · Fixed by #9432
Closed
Tracked by #8673

Error logging when SegmentMerge task is cancelled by segment invalidation #7502

JaySon-Huang opened this issue May 18, 2023 · 3 comments · Fixed by #9432
Labels
component/storage type/enhancement The issue or PR belongs to an enhancement.

Comments

@JaySon-Huang
Copy link
Contributor

Bug Report

Please answer these questions before submitting your issue. Thanks!

1. Minimal reproduce step (Required)

Notice a WriteBatchesImpl deconstruction error logging

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

Seems this is a possible routine and we don't need error logging for it. Maybe we can clear the WriteBatches when we check the segment becomes invalidation to avoid this logging?

Anyway, it does not affect the tiflash normally running.

3. What did you see instead (Required)

[2023/05/18 06:45:41.222 +00:00] [DEBUG] [DeltaMergeStore_InternalSegment.cpp:637] ["Segment instance is abandoned, segment=<segment_id=2065428 epoch=5 range=[986649538,986679568) abandoned=true>"] [source="keyspace_id=4294967295 table_id=99"] [thread_id=349]
[2023/05/18 06:45:41.222 +00:00] [DEBUG] [DeltaMergeStore_InternalSegment.cpp:298] ["Merge - Give up segmentMerge because not valid, segment=<segment_id=2065428 epoch=5 range=[986649538,986679568) abandoned=true>"] [source="keyspace_id=4294967295 table_id=99"] [thread_id=349]
[2023/05/18 06:45:44.675 +00:00] [ERROR] [WriteBatchesImpl.h:72] ["!!!=========================Modifications in meta haven't persisted=========================!!! Stack trace: \n       0x1b91a33\tStackTrace::StackTrace() [tiflash+28908083]\n                \tdbms/src/Common/StackTrace.cpp:23\n       0x7243c37\tDB::DM::WriteBatches::~WriteBatches()::'lambda'(DB::WriteBatchWrapper const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&)::operator()(DB::WriteBatchWrapper const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&) const [tiflash+119815223]\n                \tdbms/src/Storages/DeltaMerge/WriteBatchesImpl.h:68\n       0x723fe58\tDB::DM::WriteBatches::~WriteBatches() [tiflash+119799384]\n                \tdbms/src/Storages/DeltaMerge/WriteBatchesImpl.h:77\n       0x7267a43\tDB::DM::DeltaMergeStore::segmentMerge(DB::DM::DMContext&, std::__1::vector<std::__1::shared_ptr<DB::DM::Segment>, std::__1::allocator<std::__1::shared_ptr<DB::DM::Segment> > > const&, DB::DM::DeltaMergeStore::SegmentMergeReason) [tiflash+119962179]\n                \tdbms/src/Storages/DeltaMerge/DeltaMergeStore_InternalSegment.cpp:344\n       0x725844d\tDB::DM::DeltaMergeStore::gcTrySegmentMerge(std::__1::shared_ptr<DB::DM::DMContext> const&, std::__1::shared_ptr<DB::DM::Segment> const&) [tiflash+119899213]\n                \tdbms/src/Storages/DeltaMerge/DeltaMergeStore_InternalBg.cpp:683\n       0x725a224\tDB::DM::DeltaMergeStore::onSyncGc(long, DB::DM::GCOptions const&) [tiflash+119906852]\n                \tdbms/src/Storages/DeltaMerge/DeltaMergeStore_InternalBg.cpp:889\n       0x7fcaa9f\tDB::GCManager::work() [tiflash+133999263]\n                \tdbms/src/Storages/GCManager.cpp:105\n       0x7dd647d\tDB::BackgroundProcessingPool::threadFunction(unsigned long) [tiflash+131949693]\n                \tdbms/src/Storages/BackgroundProcessingPool.cpp:234\n       0x7dd6e65\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, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> >)::$_1> >(void*) [tiflash+131952229]\n                \t/usr/local/bin/../include/c++/v1/thread:291\n  0x7f81af0fc609\tstart_thread [libpthread.so.0+34313]\n                \t/build/glibc-SzIz7B/glibc-2.31/nptl/pthread_create.c:477\n  0x7f81aef41133\tclone [libc.so.6+1175859]\n                \t/build/glibc-SzIz7B/glibc-2.31/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:95"] [thread_id=349]
[2023/05/18 06:45:44.678 +00:00] [DEBUG] [DeltaMergeStore_InternalSegment.cpp:637] ["Segment instance is abandoned, segment=<segment_id=2065428 epoch=5 range=[986649538,986679568) abandoned=true>"] [source="keyspace_id=4294967295 table_id=99"] [thread_id=349]

4. What is your TiFlash version? (Required)

b8db481

@JaySon-Huang JaySon-Huang added type/bug The issue is confirmed as a bug. severity/moderate component/storage type/enhancement The issue or PR belongs to an enhancement. and removed type/bug The issue is confirmed as a bug. severity/moderate labels May 18, 2023
@JaySon-Huang
Copy link
Contributor Author

Change it to enhancement because it does not affect the tiflash functionality

@CalvinNeo
Copy link
Member

[2024/01/08 06:02:48.069 +00:00] [DEBUG] [DeltaMergeStore_InternalSegment.cpp:702] ["Segment instance is abandoned, segment=<segment_id=1863 epoch=3 range=[24406601,24644220) abandoned=true>"] [source="keyspace=4294967295 table_id=139"] [thread_id=422]
[2024/01/08 06:02:48.069 +00:00] [DEBUG] [DeltaMergeStore_InternalSegment.cpp:322] ["Merge - Give up segmentMerge because not valid, segment=<segment_id=1863 epoch=3 range=[24406601,24644220) abandoned=true>"] [source="keyspace=4294967295 table_id=139"] [thread_id=422]

[2024/01/08 06:02:51.427 +00:00] [ERROR] [WriteBatchesImpl.h:74] ["!!!=========================Modifications in meta haven't persisted=========================!!! Stack trace: 
  0x56367772a5e3    StackTrace::StackTrace() [tiflash+34481635]
                    dbms/src/Common/StackTrace.cpp:23
  0x56367cd3a399    DB::DM::WriteBatches::~WriteBatches()::'lambda'(DB::WriteBatchWrapper const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char>> const&)::operator()(DB::WriteBatchWrapper const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char>> const&) const [tiflash+124724121]
                    dbms/src/Storages/DeltaMerge/WriteBatchesImpl.h:68
  0x56367cd36b0a    DB::DM::WriteBatches::~WriteBatches() [tiflash+124709642]
                    dbms/src/Storages/DeltaMerge/WriteBatchesImpl.h:79
  0x56367cd641fe    DB::DM::DeltaMergeStore::segmentMerge(DB::DM::DMContext&, std::__1::vector<std::__1::shared_ptr<DB::DM::Segment>, std::__1::allocator<std::__1::shared_ptr<DB::DM::Segment>>> const&, DB::DM::DeltaMergeStore::SegmentMergeReason) [tiflash+124895742]
                    dbms/src/Storages/DeltaMerge/DeltaMergeStore_InternalSegment.cpp:368
  0x56367cd524a9    DB::DM::DeltaMergeStore::gcTrySegmentMerge(std::__1::shared_ptr<DB::DM::DMContext> const&, std::__1::shared_ptr<DB::DM::Segment> const&) [tiflash+124822697]
                    dbms/src/Storages/DeltaMerge/DeltaMergeStore_InternalBg.cpp:722
  0x56367cd54028    DB::DM::DeltaMergeStore::onSyncGc(long, DB::DM::GCOptions const&) [tiflash+124829736]
                    dbms/src/Storages/DeltaMerge/DeltaMergeStore_InternalBg.cpp:933
  0x56367e5eae03    DB::GCManager::work() [tiflash+150613507]
                    dbms/src/Storages/GCManager.cpp:108
  0x56367d9ab3fb    DB::BackgroundProcessingPool::threadFunction(unsigned long) [tiflash+137769979]
                    /usr/local/bin/../include/c++/v1/__functional/function.h:512
  0x56367d9abdf5    void* std::__1::__thread_proxy[abi:v15007]<std::__1::tuple<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct>>, DB::BackgroundProcessingPool::BackgroundProcessingPool(int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char>>)::$_2>>(void*) [tiflash+137772533]
                    dbms/src/Storages/BackgroundProcessingPool.cpp:95
  0x7f37a026d609    start_thread [libpthread.so.0+34313]
                    /build/glibc-wuryBv/glibc-2.31/nptl/pthread_create.c:477
  0x7f37a00b2353    clone [libc.so.6+1176403]
                    /build/glibc-wuryBv/glibc-2.31/misc/../sysdeps/unix/sysv/linux/x86_64/clone.S:95"] [thread_id=422]

@breezewish
Copy link
Member

[2024/06/07 10:12:56.571 +08:00] [DEBUG] [DeltaMergeStore_InternalSegment.cpp:971] ["Segment instance has been replaced in segment map, segment=<segment_id=930 epoch=0 range=[16001,9223372036854775807)>"] [source="keyspace=1 table_id=105"] [thread_id=221]
[2024/06/07 10:12:56.571 +08:00] [DEBUG] [DeltaMergeStore_InternalSegment.cpp:176] ["Split - Give up segmentSplit because not valid, segment=<segment_id=930 epoch=0 range=[16001,9223372036854775807)>"] [source="keyspace=1 table_id=105"] [thread_id=221]
[2024/06/07 10:12:57.059 +08:00] [ERROR] [WriteBatchesImpl.h:74] ["!!!=========================Modifications in meta haven't persisted=========================!!! Stack trace: \n     0x100ac21d0\tStackTrace::StackTrace() [tiflash+4295533008]\n                \tdbms/src/Common/StackTrace.cpp:22\n     0x105ba01d0\tDB::DM::WriteBatches::~WriteBatches()::'lambda'(DB::WriteBatchWrapper const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char>> const&)::operator()(DB::WriteBatchWrapper const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char>> const&) const [tiflash+4380328400]\n                \tdbms/src/Storages/DeltaMerge/WriteBatchesImpl.h:68\n     0x105b9fd14\tDB::DM::WriteBatches::~WriteBatches() [tiflash+4380327188]\n                \tdbms/src/Storages/DeltaMerge/WriteBatchesImpl.h:79\n     0x105bd5128\tDB::DM::DeltaMergeStore::segmentSplit(DB::DM::DMContext&, std::__1::shared_ptr<DB::DM::Segment> const&, DB::DM::DeltaMergeStore::SegmentSplitReason, std::__1::optional<DB::DM::RowKeyValue>, DB::DM::DeltaMergeStore::SegmentSplitMode) [tiflash+4380545320]\n                \tdbms/src/Storages/DeltaMerge/DeltaMergeStore_InternalSegment.cpp:251\n     0x105bc5300\tDB::DM::DeltaMergeStore::handleBackgroundTask(bool) [tiflash+4380480256]\n                \tdbms/src/Storages/DeltaMerge/DeltaMergeStore_InternalBg.cpp:397\n     0x106c5740c\tDB::BackgroundProcessingPool::threadFunction(unsigned long) [tiflash+4397855756]\n                \tdbms/src/Storages/BackgroundProcessingPool.cpp:265\n     0x106c58064\tvoid* std::__1::__thread_proxy[abi:ue170006]<std::__1::tuple<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct>>, DB::BackgroundProcessingPool::BackgroundProcessingPool(int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char>>, std::__1::shared_ptr<DB::JointThreadInfoJeallocMap>)::$_2>>(void*) [tiflash+4397858916]\n                \t/Library/Developer/CommandLineTools/SDKs/MacOSX14.4.sdk/usr/include/c++/v1/__thread/thread.h:238\n     0x18bf81034\t__pthread_joiner_wake [libsystem_pthread.dylib+6446878772]\n     0x18bf7be3c\t__pthread_mutex_global_init [libsystem_pthread.dylib+6446857788]"] [thread_id=221]
[2024/06/07 10:12:57.059 +08:00] [ERROR] [WriteBatchesImpl.h:74] ["!!!=========================Modifications in removed_data haven't persisted=========================!!! Stack trace: \n     0x100ac21d0\tStackTrace::StackTrace() [tiflash+4295533008]\n                \tdbms/src/Common/StackTrace.cpp:22\n     0x105ba01d0\tDB::DM::WriteBatches::~WriteBatches()::'lambda'(DB::WriteBatchWrapper const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char>> const&)::operator()(DB::WriteBatchWrapper const&, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char>> const&) const [tiflash+4380328400]\n                \tdbms/src/Storages/DeltaMerge/WriteBatchesImpl.h:68\n     0x105b9fdac\tDB::DM::WriteBatches::~WriteBatches() [tiflash+4380327340]\n                \tdbms/src/Storages/DeltaMerge/WriteBatchesImpl.h:81\n     0x105bd5128\tDB::DM::DeltaMergeStore::segmentSplit(DB::DM::DMContext&, std::__1::shared_ptr<DB::DM::Segment> const&, DB::DM::DeltaMergeStore::SegmentSplitReason, std::__1::optional<DB::DM::RowKeyValue>, DB::DM::DeltaMergeStore::SegmentSplitMode) [tiflash+4380545320]\n                \tdbms/src/Storages/DeltaMerge/DeltaMergeStore_InternalSegment.cpp:251\n     0x105bc5300\tDB::DM::DeltaMergeStore::handleBackgroundTask(bool) [tiflash+4380480256]\n                \tdbms/src/Storages/DeltaMerge/DeltaMergeStore_InternalBg.cpp:397\n     0x106c5740c\tDB::BackgroundProcessingPool::threadFunction(unsigned long) [tiflash+4397855756]\n                \tdbms/src/Storages/BackgroundProcessingPool.cpp:265\n     0x106c58064\tvoid* std::__1::__thread_proxy[abi:ue170006]<std::__1::tuple<std::__1::unique_ptr<std::__1::__thread_struct, std::__1::default_delete<std::__1::__thread_struct>>, DB::BackgroundProcessingPool::BackgroundProcessingPool(int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char>>, std::__1::shared_ptr<DB::JointThreadInfoJeallocMap>)::$_2>>(void*) [tiflash+4397858916]\n                \t/Library/Developer/CommandLineTools/SDKs/MacOSX14.4.sdk/usr/include/c++/v1/__thread/thread.h:238\n     0x18bf81034\t__pthread_joiner_wake [libsystem_pthread.dylib+6446878772]\n     0x18bf7be3c\t__pthread_mutex_global_init [libsystem_pthread.dylib+6446857788]"] [thread_id=221]

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
component/storage type/enhancement The issue or PR belongs to an enhancement.
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants