FAP: Panic when a task throws without generate any result

[CalvinNeo]

Bug Report

Please answer these questions before submitting your issue. Thanks!

[root@tc-tiflash-0 logs]# cat server.log | grep "region_id=2953"
[2024/04/25 07:39:28.919 +00:00] [INFO] [FastAddPeer.cpp:657] ["Add new task success, new_peer_id=32608 region_id=2953"] [source=FastAddPeer] [thread_id=20]
[2024/04/25 07:39:40.536 +00:00] [INFO] [FastAddPeer.cpp:243] ["Select checkpoint with data_seq=30, remote_store_id=2163 elapsed=5.155632808 size(candidate_store_id)=2 region_id=2953"] [source=FastAddPeer] [thread_id=34]
[2024/04/25 07:39:40.536 +00:00] [INFO] [DeltaMergeStore_Ingest.cpp:1127] ["Build checkpoint from remote, store_id=2163 region_id=2953"] [source="keyspace=1 table_id=2684"] [thread_id=34]
[2024/04/25 07:39:51.824 +00:00] [INFO] [DeltaMergeStore_Ingest.cpp:1159] ["Build checkpoint from remote failed for deadline exceed, <key=<s2163/data/ks_1_t_2684/dmf_2370,2138,30>,type=AddLock>, region_id=2953 remote_store_id=2163"] [source="keyspace=1 table_id=2684"] [thread_id=34]
[2024/04/25 07:39:51.824 +00:00] [ERROR] [Exception.cpp:96] ["Failed when try to restore from checkpoint region_id=2953 new_peer_id=32608 deadline exceed, <key=<s2163/data/ks_1_t_2684/dmf_2370,2138,30>,type=AddLock>: Code: 159, e.displayText() = DB::Exception: deadline exceed, <key=<s2163/data/ks_1_t_2684/dmf_2370,2138,30>,type=AddLock>, e.what() = DB::Exception, Stack trace:\n\n\n       0x1f94c30\tDB::Exception::Exception<>(int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&) [tiflash+33115184]\n                \tdbms/src/Common/Exception.h:53\n       0x8a8a659\tDB::S3::S3LockClient::sendTryAddLockRequest(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, unsigned int, unsigned int, long) [tiflash+145270361]\n                \tdbms/src/Flash/Disaggregated/S3LockClient.cpp:62\n       0x86e42f0\tDB::PS::V3::S3LockLocalManager::createS3LockForWriteBatch(DB::UniversalWriteBatch&) [tiflash+141443824]\n                \tdbms/src/Storages/Page/V3/Universal/S3LockLocalManager.cpp:173\n       0x86d9139\tDB::UniversalPageStorage::write(DB::UniversalWriteBatch&&, DB::PS::V3::PageType, std::__1::shared_ptr<DB::WriteLimiter> const&) const [tiflash+141398329]\n                \tdbms/src/Storages/Page/V3/Universal/UniversalPageStorage.cpp:118\n       0x865758c\tDB::PageWriter::write(DB::WriteBatchWrapper&&, std::__1::shared_ptr<DB::WriteLimiter>) const [tiflash+140866956]\n                \tdbms/src/Storages/Page/PageStorage.cpp:621\n       0x7536c63\tDB::DM::WriteBatches::writeLogAndData() [tiflash+122907747]\n                \tdbms/src/Storages/DeltaMerge/WriteBatchesImpl.h:146\n       0x762a215\tDB::DM::StableValueSpace::createFromCheckpoint(std::__1::shared_ptr<DB::Logger> const&, DB::DM::DMContext&, std::__1::shared_ptr<DB::UniversalPageStorage>, unsigned long, DB::DM::WriteBatches&) [tiflash+123904533]\n                \tdbms/src/Storages/DeltaMerge/StableValueSpace.cpp:224\n       0x75a18e2\tDB::DM::Segment::createTargetSegmentsFromCheckpoint(std::__1::shared_ptr<DB::Logger> const&, DB::DM::DMContext&, unsigned long, std::__1::vector<DB::DM::Segment::SegmentMetaInfo, std::__1::allocator<DB::DM::Segment::SegmentMetaInfo> > const&, DB::DM::RowKeyRange const&, std::__1::shared_ptr<DB::UniversalPageStorage>, DB::DM::WriteBatches&) [tiflash+123345122]\n                \tdbms/src/Storages/DeltaMerge/Segment.cpp:488\n       0x758de06\tDB::DM::DeltaMergeStore::buildSegmentsFromCheckpointInfo(std::__1::shared_ptr<DB::DM::DMContext> const&, DB::DM::RowKeyRange const&, std::__1::shared_ptr<DB::CheckpointInfo> const&) const [tiflash+123264518]\n                \tdbms/src/Storages/DeltaMerge/DeltaMergeStore_Ingest.cpp:1132\n       0x8089a6a\tDB::DM::DeltaMergeStore::buildSegmentsFromCheckpointInfo(DB::Context const&, DB::Settings const&, DB::DM::RowKeyRange const&, std::__1::shared_ptr<DB::CheckpointInfo> const&) [tiflash+134781546]\n                \tdbms/src/Storages/DeltaMerge/DeltaMergeStore.h:357\n       0x8b1f38e\tstd::__1::__function::__func<FastAddPeer::$_29, std::__1::allocator<FastAddPeer::$_29>, DB::FastAddPeerRes ()>::operator()() [tiflash+145879950]\n                \t/usr/local/bin/../include/c++/v1/__functional/function.h:345\n       0x8b1e411\tstd::__1::__function::__func<DB::AsyncTasks<unsigned long, std::__1::function<DB::FastAddPeerRes ()>, DB::FastAddPeerRes>::addTaskWithCancel(unsigned long, std::__1::function<DB::FastAddPeerRes ()>, std::__1::function<void ()>)::'lambda'(), std::__1::allocator<DB::AsyncTasks<unsigned long, std::__1::function<DB::FastAddPeerRes ()>, DB::FastAddPeerRes>::addTaskWithCancel(unsigned long, std::__1::function<DB::FastAddPeerRes ()>, std::__1::function<void ()>)::'lambda'()>, void ()>::operator()() [tiflash+145875985]\n                \t/usr/local/bin/../include/c++/v1/__functional/function.h:345\n       0x1fb4d07\tDB::ThreadPoolImpl<DB::ThreadFromGlobalPoolImpl<false> >::worker(std::__1::__list_iterator<DB::ThreadFromGlobalPoolImpl<false>, void*>) [tiflash+33246471]\n                \tdbms/src/Common/UniThreadPool.cpp:306\n       0x1fb6fa3\tstd::__1::__function::__func<DB::ThreadFromGlobalPoolImpl<false>::ThreadFromGlobalPoolImpl<bool DB::ThreadPoolImpl<DB::ThreadFromGlobalPoolImpl<false> >::scheduleImpl<bool>(std::__1::function<void ()>, long, std::__1::optional<unsigned long>, bool)::'lambda0'()>(bool&&)::'lambda'(), std::__1::allocator<DB::ThreadFromGlobalPoolImpl<false>::ThreadFromGlobalPoolImpl<bool DB::ThreadPoolImpl<DB::ThreadFromGlobalPoolImpl<false> >::scheduleImpl<bool>(std::__1::function<void ()>, long, std::__1::optional<unsigned long>, bool)::'lambda0'()>(bool&&)::'lambda'()>, void ()>::operator()() [tiflash+33255331]\n                \t/usr/local/bin/../include/c++/v1/__functional/function.h:345\n       0x1fb5de8\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::ThreadPoolImpl<std::__1::thread>::scheduleImpl<void>(std::__1::function<void ()>, long, std::__1::optional<unsigned long>, bool)::'lambda0'()> >(void*) [tiflash+33250792]\n                \t/usr/local/bin/../include/c++/v1/thread:291\n  0x7f9449970ea5\tstart_thread [libpthread.so.0+32421]\n  0x7f944927f96d\t__clone [libc.so.6+1042797]"] [source=FastAddPeerImpl] [thread_id=34]
[2024/04/25 07:43:58.200 +00:00] [INFO] [SSTFilesToBlockInputStream.cpp:129] ["Finish Construct MultiSSTReader, write=1 lock=1 default=0 region_id=2953 snapshot_index=69106"] [source="keyspace=1 table_id=2684"] [thread_id=24]
[2024/04/25 07:43:58.200 +00:00] [INFO] [PrehandleSnapshot.cpp:644] ["Single threaded prehandling for single big region, range=[7800000174800000FF0000000A7C5F7280FF0000001183204200FE,7800000174800000FF0000000A7C5F72FFFFFFFFFFFFFFFFFF00FF0000000000000000F7], region_id=2953"] [thread_id=24]
[2024/04/25 07:44:02.128 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=69106] file_idx=0 file_rows=1007616 file_bytes=95723520 data_range=[293806146,294813542) file_bytes_on_disk=35688395 file=/data0/db/data/ks_1_t_2684/stable/dmf_2035"] [source="keyspace=1 table_id=2684"] [thread_id=24]
[2024/04/25 07:44:06.170 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=69106] file_idx=1 file_rows=1007616 file_bytes=95723520 data_range=[294813542,295821996) file_bytes_on_disk=35956925 file=/data0/db/data/ks_1_t_2684/stable/dmf_2036"] [source="keyspace=1 table_id=2684"] [thread_id=24]
[2024/04/25 07:44:10.959 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=69106] file_idx=2 file_rows=1007616 file_bytes=95723520 data_range=[295821996,296829192) file_bytes_on_disk=35768996 file=/data0/db/data/ks_1_t_2684/stable/dmf_2037"] [source="keyspace=1 table_id=2684"] [thread_id=24]
[2024/04/25 07:44:15.224 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=69106] file_idx=3 file_rows=1007616 file_bytes=95723520 data_range=[296829192,297836207) file_bytes_on_disk=35809599 file=/data0/db/data/ks_1_t_2684/stable/dmf_2038"] [source="keyspace=1 table_id=2684"] [thread_id=24]
[2024/04/25 07:44:19.045 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=69106] file_idx=4 file_rows=1007616 file_bytes=95723520 data_range=[297836207,298844383) file_bytes_on_disk=35803997 file=/data0/db/data/ks_1_t_2684/stable/dmf_2039"] [source="keyspace=1 table_id=2684"] [thread_id=24]
[2024/04/25 07:44:23.095 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=69106] file_idx=5 file_rows=1007616 file_bytes=95723520 data_range=[298844383,299853023) file_bytes_on_disk=35843714 file=/data0/db/data/ks_1_t_2684/stable/dmf_2040"] [source="keyspace=1 table_id=2684"] [thread_id=24]
[2024/04/25 07:44:25.442 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=69106] file_idx=6 file_rows=602779 file_bytes=57264005 data_range=[299853023,300651385) file_bytes_on_disk=23143096 file=/data0/db/data/ks_1_t_2684/stable/dmf_2041"] [source="keyspace=1 table_id=2684"] [thread_id=24]
[2024/04/25 07:44:25.442 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:130] ["Transformed snapshot in SSTFile to DTFiles, region=[region_id=2953 applied_term=6 applied_index=69106] job_type=ApplySnapshot cost_ms=27241 rows=6648475 bytes=631605125 bytes_on_disk=238014722 write_cf_keys=6648475 default_cf_keys=0 lock_cf_keys=54 splid_id=18446744073709551615 dt_files=[files_num=7 dmf_2035,dmf_2036,dmf_2037,dmf_2038,dmf_2039,dmf_2040,dmf_2041]"] [source="keyspace=1 table_id=2684"] [thread_id=24]
[2024/04/25 07:44:28.048 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:156] ["Upload snapshot DTFiles done, region=[region_id=2953 applied_term=6 applied_index=69106] store_id=2138 n_dt_files=7 cost=2.606s"] [source="keyspace=1 table_id=2684"] [thread_id=24]
[2024/04/25 07:44:28.048 +00:00] [INFO] [ApplySnapshot.cpp:319] ["Begin apply snapshot, new_region=[region_id=2953 applied_term=6 applied_index=69106]"] [thread_id=23]
[2024/04/25 07:44:28.077 +00:00] [FATAL] [Exception.cpp:106] ["Code: 49, e.displayText() = DB::Exception: Check prev_state == FAPAsyncTasks::TaskState::NotScheduled failed: FastAddPeer: find scheduled fap task, region_id=2953 fap_state=Finished is_regular_snapshot=true: (while applyPreHandledSnapshot region_id=2953), e.what() = DB::Exception, Stack trace:\n\n\n       0x1ecba7e\tDB::Exception::Exception(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, int) [tiflash+32291454]\n                \tdbms/src/Common/Exception.h:46\n       0x8b3547a\tDB::FastAddPeerContext::resolveFapSnapshotState(DB::TMTContext&, DB::TiFlashRaftProxyHelper const*, unsigned long, bool) [tiflash+145970298]\n                \tdbms/src/Storages/KVStore/MultiRaft/Disagg/FastAddPeerContext.cpp:245\n       0x8aa7854\tvoid DB::KVStore::checkAndApplyPreHandledSnapshot<DB::RegionPtrWithSnapshotFiles>(DB::RegionPtrWithSnapshotFiles const&, DB::TMTContext&) [tiflash+145389652]\n                \tdbms/src/Storages/KVStore/MultiRaft/ApplySnapshot.cpp:128\n       0x8aa66d0\tvoid DB::KVStore::applyPreHandledSnapshot<DB::RegionPtrWithSnapshotFiles>(DB::RegionPtrWithSnapshotFiles const&, DB::TMTContext&) [tiflash+145385168]\n                \tdbms/src/Storages/KVStore/MultiRaft/ApplySnapshot.cpp:327\n       0x8a9910a\tApplyPreHandledSnapshot [tiflash+145330442]\n                \tdbms/src/Storages/KVStore/FFI/ProxyFFI.cpp:693\n  0x7f944b98effc\t_$LT$engine_store_ffi..observer..TiFlashObserver$LT$T$C$ER$GT$$u20$as$u20$raftstore..coprocessor..ApplySnapshotObserver$GT$::post_apply_snapshot::h427945d65ce188cf [libtiflash_proxy.so+26214396]\n  0x7f944c915649\traftstore::store::worker::region::Runner$LT$EK$C$R$C$T$GT$::handle_pending_applies::hab871494553185a2 [libtiflash_proxy.so+42493513]\n  0x7f944bf7d1df\tyatp::task::future::RawTask$LT$F$GT$::poll::hf33305e587d2c9fd [libtiflash_proxy.so+32432607]\n  0x7f944d86dd7b\t_$LT$yatp..task..future..Runner$u20$as$u20$yatp..pool..runner..Runner$GT$::handle::h3c8ad78cdc484f59 [libtiflash_proxy.so+58584443]\n  0x7f944baa5fc4\tstd::sys_common::backtrace::__rust_begin_short_backtrace::h37aa3ec1d0c1d3f0 [libtiflash_proxy.so+27357124]\n  0x7f944baeb388\tcore::ops::function::FnOnce::call_once$u7b$$u7b$vtable.shim$u7d$$u7d$::h70659c9e4b989e59 [libtiflash_proxy.so+27640712]\n  0x7f944cf98525\tstd::sys::unix::thread::Thread::new::thread_start::hd2791a9cabec1fda [libtiflash_proxy.so+49321253]\n                \t/rustc/96ddd32c4bfb1d78f0cd03eb068b1710a8cebeef/library/std/src/sys/unix/thread.rs:108\n  0x7f9449970ea5\tstart_thread [libpthread.so.0+32421]\n  0x7f944927f96d\t__clone [libc.so.6+1042797]"] [source="void DB::ApplyPreHandledSnapshot(DB::EngineStoreServerWrap *, DB::RawVoidPtr, DB::RawCppPtrType)"] [thread_id=23]
[2024/04/25 07:51:13.869 +00:00] [INFO] [SSTFilesToBlockInputStream.cpp:129] ["Finish Construct MultiSSTReader, write=1 lock=1 default=0 region_id=2953 snapshot_index=69106"] [source="keyspace=1 table_id=2684"] [thread_id=236]
[2024/04/25 07:51:13.869 +00:00] [INFO] [PrehandleSnapshot.cpp:644] ["Single threaded prehandling for single big region, range=[7800000174800000FF0000000A7C5F7280FF0000001183204200FE,7800000174800000FF0000000A7C5F72FFFFFFFFFFFFFFFFFF00FF0000000000000000F7], region_id=2953"] [thread_id=236]
[2024/04/25 07:51:16.301 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=69106] file_idx=0 file_rows=1007616 file_bytes=95723520 data_range=[293806146,294813542) file_bytes_on_disk=35688395 file=/data0/db/data/ks_1_t_2684/stable/dmf_2696"] [source="keyspace=1 table_id=2684"] [thread_id=236]
[2024/04/25 07:51:18.647 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=69106] file_idx=1 file_rows=1007616 file_bytes=95723520 data_range=[294813542,295821996) file_bytes_on_disk=35956925 file=/data0/db/data/ks_1_t_2684/stable/dmf_2697"] [source="keyspace=1 table_id=2684"] [thread_id=236]
[2024/04/25 07:51:21.001 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=69106] file_idx=2 file_rows=1007616 file_bytes=95723520 data_range=[295821996,296829192) file_bytes_on_disk=35768996 file=/data0/db/data/ks_1_t_2684/stable/dmf_2698"] [source="keyspace=1 table_id=2684"] [thread_id=236]
[2024/04/25 07:51:23.370 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=69106] file_idx=3 file_rows=1007616 file_bytes=95723520 data_range=[296829192,297836207) file_bytes_on_disk=35809599 file=/data0/db/data/ks_1_t_2684/stable/dmf_2699"] [source="keyspace=1 table_id=2684"] [thread_id=236]
[2024/04/25 07:51:25.742 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=69106] file_idx=4 file_rows=1007616 file_bytes=95723520 data_range=[297836207,298844383) file_bytes_on_disk=35803997 file=/data0/db/data/ks_1_t_2684/stable/dmf_2700"] [source="keyspace=1 table_id=2684"] [thread_id=236]
[2024/04/25 07:51:28.119 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=69106] file_idx=5 file_rows=1007616 file_bytes=95723520 data_range=[298844383,299853023) file_bytes_on_disk=35843714 file=/data0/db/data/ks_1_t_2684/stable/dmf_2701"] [source="keyspace=1 table_id=2684"] [thread_id=236]
[2024/04/25 07:51:29.522 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=69106] file_idx=6 file_rows=602779 file_bytes=57264005 data_range=[299853023,300651385) file_bytes_on_disk=23143096 file=/data0/db/data/ks_1_t_2684/stable/dmf_2702"] [source="keyspace=1 table_id=2684"] [thread_id=236]
[2024/04/25 07:51:29.522 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:130] ["Transformed snapshot in SSTFile to DTFiles, region=[region_id=2953 applied_term=6 applied_index=69106] job_type=ApplySnapshot cost_ms=15652 rows=6648475 bytes=631605125 bytes_on_disk=238014722 write_cf_keys=6648475 default_cf_keys=0 lock_cf_keys=54 splid_id=18446744073709551615 dt_files=[files_num=7 dmf_2696,dmf_2697,dmf_2698,dmf_2699,dmf_2700,dmf_2701,dmf_2702]"] [source="keyspace=1 table_id=2684"] [thread_id=236]
[2024/04/25 07:51:31.830 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:156] ["Upload snapshot DTFiles done, region=[region_id=2953 applied_term=6 applied_index=69106] store_id=2138 n_dt_files=7 cost=2.308s"] [source="keyspace=1 table_id=2684"] [thread_id=236]
[2024/04/25 07:51:31.831 +00:00] [INFO] [ApplySnapshot.cpp:319] ["Begin apply snapshot, new_region=[region_id=2953 applied_term=6 applied_index=69106]"] [thread_id=208]
[2024/04/25 07:51:31.831 +00:00] [INFO] [CheckpointIngestInfo.cpp:276] ["Erase CheckpointIngestInfo from disk by force, region_id=2953 exist=false in_memory=false reason=ResolveStateApplySnapshot"] [thread_id=208]
[2024/04/25 07:51:31.972 +00:00] [INFO] [RegionTable.cpp:453] ["insert internal region, keyspace=1 table_id=2684 region_id=2953"] [thread_id=208]
[2024/04/25 07:51:31.972 +00:00] [INFO] [KVStore.cpp:398] ["Start to persist [region_id=2953 applied_term=6 applied_index=69106], cache size: 0 bytes for `save current region after apply `"] [thread_id=208]
[2024/04/25 07:51:31.973 +00:00] [INFO] [ApplySnapshot.cpp:332] ["Finish apply snapshot, cost=0.142s region_id=2953"] [thread_id=208]
[2024/04/25 07:54:36.473 +00:00] [INFO] [SSTFilesToBlockInputStream.cpp:129] ["Finish Construct MultiSSTReader, write=1 lock=1 default=0 region_id=2953 snapshot_index=812909"] [source="keyspace=1 table_id=2684"] [thread_id=236]
[2024/04/25 07:54:36.473 +00:00] [INFO] [PrehandleSnapshot.cpp:644] ["Single threaded prehandling for single big region, range=[7800000174800000FF0000000A7C5F7280FF0000001183204200FE,7800000174800000FF0000000A7C5F72FFFFFFFFFFFFFFFFFF00FF0000000000000000F7], region_id=2953"] [thread_id=236]
[2024/04/25 07:54:41.692 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=812909] file_idx=0 file_rows=1005140 file_bytes=95488300 data_range=[293806146,294806474) file_bytes_on_disk=35599658 file=/data0/db/data/ks_1_t_2684/stable/dmf_3193"] [source="keyspace=1 table_id=2684"] [thread_id=236]
[2024/04/25 07:54:45.698 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=812909] file_idx=1 file_rows=1004329 file_bytes=95411255 data_range=[294806474,295806349) file_bytes_on_disk=35788347 file=/data0/db/data/ks_1_t_2684/stable/dmf_3230"] [source="keyspace=1 table_id=2684"] [thread_id=236]
[2024/04/25 07:54:49.382 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=812909] file_idx=2 file_rows=1005425 file_bytes=95515375 data_range=[295806349,296806656) file_bytes_on_disk=35705069 file=/data0/db/data/ks_1_t_2684/stable/dmf_3317"] [source="keyspace=1 table_id=2684"] [thread_id=236]
[2024/04/25 07:54:53.305 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=812909] file_idx=3 file_rows=1004977 file_bytes=95472815 data_range=[296806656,297806879) file_bytes_on_disk=35729966 file=/data0/db/data/ks_1_t_2684/stable/dmf_3321"] [source="keyspace=1 table_id=2684"] [thread_id=236]
[2024/04/25 07:54:57.282 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=812909] file_idx=4 file_rows=1004990 file_bytes=95474050 data_range=[297806879,298807942) file_bytes_on_disk=35676981 file=/data0/db/data/ks_1_t_2684/stable/dmf_3322"] [source="keyspace=1 table_id=2684"] [thread_id=236]
[2024/04/25 07:55:01.397 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=812909] file_idx=5 file_rows=1005010 file_bytes=95475950 data_range=[298807942,299809064) file_bytes_on_disk=35797601 file=/data0/db/data/ks_1_t_2684/stable/dmf_3325"] [source="keyspace=1 table_id=2684"] [thread_id=236]
[2024/04/25 07:55:05.122 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=812909] file_idx=6 file_rows=1006436 file_bytes=95611420 data_range=[299809064,301003340) file_bytes_on_disk=40087903 file=/data0/db/data/ks_1_t_2684/stable/dmf_3335"] [source="keyspace=1 table_id=2684"] [thread_id=236]
[2024/04/25 07:55:08.925 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=812909] file_idx=7 file_rows=1007616 file_bytes=95723520 data_range=[301003340,302011101) file_bytes_on_disk=43280134 file=/data0/db/data/ks_1_t_2684/stable/dmf_3345"] [source="keyspace=1 table_id=2684"] [thread_id=236]
[2024/04/25 07:55:12.743 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=812909] file_idx=8 file_rows=1007616 file_bytes=95723520 data_range=[302011101,303018848) file_bytes_on_disk=43303399 file=/data0/db/data/ks_1_t_2684/stable/dmf_3356"] [source="keyspace=1 table_id=2684"] [thread_id=236]
[2024/04/25 07:55:13.082 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=812909] file_idx=9 file_rows=99258 file_bytes=9429510 data_range=[303018848,303129060) file_bytes_on_disk=4267340 file=/data0/db/data/ks_1_t_2684/stable/dmf_3368"] [source="keyspace=1 table_id=2684"] [thread_id=236]
[2024/04/25 07:55:13.082 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:130] ["Transformed snapshot in SSTFile to DTFiles, region=[region_id=2953 applied_term=6 applied_index=812909] job_type=ApplySnapshot cost_ms=36609 rows=9150797 bytes=869325715 bytes_on_disk=345236398 write_cf_keys=9167802 default_cf_keys=0 lock_cf_keys=0 splid_id=18446744073709551615 dt_files=[files_num=10 dmf_3193,dmf_3230,dmf_3317,dmf_3321,dmf_3322,dmf_3325,dmf_3335,dmf_3345,dmf_3356,dmf_3368]"] [source="keyspace=1 table_id=2684"] [thread_id=236]
[2024/04/25 07:55:16.722 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:156] ["Upload snapshot DTFiles done, region=[region_id=2953 applied_term=6 applied_index=812909] store_id=2138 n_dt_files=10 cost=3.639s"] [source="keyspace=1 table_id=2684"] [thread_id=236]
[2024/04/25 07:55:16.722 +00:00] [INFO] [ApplySnapshot.cpp:319] ["Begin apply snapshot, new_region=[region_id=2953 applied_term=6 applied_index=812909]"] [thread_id=208]
[2024/04/25 07:55:16.722 +00:00] [INFO] [ApplySnapshot.cpp:78] ["[region_id=2953 applied_term=6 applied_index=69106] set state to `Applying`"] [thread_id=208]
[2024/04/25 07:55:16.722 +00:00] [INFO] [KVStore.cpp:398] ["Start to persist [region_id=2953 applied_term=6 applied_index=69106], cache size: 0 bytes for `save previous region before apply `"] [thread_id=208]
[2024/04/25 07:55:16.723 +00:00] [INFO] [CheckpointIngestInfo.cpp:276] ["Erase CheckpointIngestInfo from disk by force, region_id=2953 exist=false in_memory=false reason=ResolveStateApplySnapshot"] [thread_id=208]
[2024/04/25 07:55:16.918 +00:00] [INFO] [RegionTable.cpp:437] ["internal region has larger range, keyspace=1 table_id=2684 region_id=2953"] [thread_id=208]
[2024/04/25 07:55:16.918 +00:00] [INFO] [KVStore.cpp:398] ["Start to persist [region_id=2953 applied_term=6 applied_index=812909], cache size: 0 bytes for `save current region after apply `"] [thread_id=208]
[2024/04/25 07:55:16.919 +00:00] [INFO] [ApplySnapshot.cpp:332] ["Finish apply snapshot, cost=0.196s region_id=2953"] [thread_id=208]
[2024/04/25 07:55:17.396 +00:00] [INFO] [SSTFilesToBlockInputStream.cpp:129] ["Finish Construct MultiSSTReader, write=1 lock=1 default=0 region_id=2953 snapshot_index=873270"] [source="keyspace=1 table_id=2684"] [thread_id=209]
[2024/04/25 07:55:17.396 +00:00] [INFO] [PrehandleSnapshot.cpp:644] ["Single threaded prehandling for single big region, range=[7800000174800000FF0000000A7C5F7280FF0000001183204200FE,7800000174800000FF0000000A7C5F72FFFFFFFFFFFFFFFFFF00FF0000000000000000F7], region_id=2953"] [thread_id=209]
[2024/04/25 07:55:22.054 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=873270] file_idx=0 file_rows=1005140 file_bytes=95488300 data_range=[293806146,294806042) file_bytes_on_disk=35595787 file=/data0/db/data/ks_1_t_2684/stable/dmf_3415"] [source="keyspace=1 table_id=2684"] [thread_id=209]
[2024/04/25 07:55:27.747 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=873270] file_idx=1 file_rows=1004329 file_bytes=95411255 data_range=[294806042,295805373) file_bytes_on_disk=35792642 file=/data0/db/data/ks_1_t_2684/stable/dmf_3426"] [source="keyspace=1 table_id=2684"] [thread_id=209]
[2024/04/25 07:55:34.611 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=873270] file_idx=2 file_rows=1005425 file_bytes=95515375 data_range=[295805373,296804979) file_bytes_on_disk=35710216 file=/data0/db/data/ks_1_t_2684/stable/dmf_3434"] [source="keyspace=1 table_id=2684"] [thread_id=209]
[2024/04/25 07:55:39.188 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=873270] file_idx=3 file_rows=1004977 file_bytes=95472815 data_range=[296804979,297804872) file_bytes_on_disk=35715219 file=/data0/db/data/ks_1_t_2684/stable/dmf_3444"] [source="keyspace=1 table_id=2684"] [thread_id=209]
[2024/04/25 07:55:43.255 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=873270] file_idx=4 file_rows=1004990 file_bytes=95474050 data_range=[297804872,298805297) file_bytes_on_disk=35674453 file=/data0/db/data/ks_1_t_2684/stable/dmf_3448"] [source="keyspace=1 table_id=2684"] [thread_id=209]
[2024/04/25 07:55:47.311 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=873270] file_idx=5 file_rows=1005010 file_bytes=95475950 data_range=[298805297,299805923) file_bytes_on_disk=35799375 file=/data0/db/data/ks_1_t_2684/stable/dmf_3449"] [source="keyspace=1 table_id=2684"] [thread_id=209]
[2024/04/25 07:55:50.535 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=873270] file_idx=6 file_rows=1006436 file_bytes=95611420 data_range=[299805923,300999921) file_bytes_on_disk=40049160 file=/data0/db/data/ks_1_t_2684/stable/dmf_3451"] [source="keyspace=1 table_id=2684"] [thread_id=209]
[2024/04/25 07:55:53.708 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=873270] file_idx=7 file_rows=1007616 file_bytes=95723520 data_range=[300999921,302007682) file_bytes_on_disk=43276089 file=/data0/db/data/ks_1_t_2684/stable/dmf_3452"] [source="keyspace=1 table_id=2684"] [thread_id=209]
[2024/04/25 07:55:56.888 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=873270] file_idx=8 file_rows=1007616 file_bytes=95723520 data_range=[302007682,303015429) file_bytes_on_disk=43302523 file=/data0/db/data/ks_1_t_2684/stable/dmf_3453"] [source="keyspace=1 table_id=2684"] [thread_id=209]
[2024/04/25 07:55:57.800 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=873270] file_idx=9 file_rows=303443 file_bytes=28827085 data_range=[303015429,303328056) file_bytes_on_disk=13044003 file=/data0/db/data/ks_1_t_2684/stable/dmf_3454"] [source="keyspace=1 table_id=2684"] [thread_id=209]
[2024/04/25 07:55:57.800 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:130] ["Transformed snapshot in SSTFile to DTFiles, region=[region_id=2953 applied_term=6 applied_index=873270] job_type=ApplySnapshot cost_ms=40403 rows=9354982 bytes=888723290 bytes_on_disk=353959467 write_cf_keys=9371987 default_cf_keys=0 lock_cf_keys=76 splid_id=18446744073709551615 dt_files=[files_num=10 dmf_3415,dmf_3426,dmf_3434,dmf_3444,dmf_3448,dmf_3449,dmf_3451,dmf_3452,dmf_3453,dmf_3454]"] [source="keyspace=1 table_id=2684"] [thread_id=209]
[2024/04/25 07:56:01.506 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:156] ["Upload snapshot DTFiles done, region=[region_id=2953 applied_term=6 applied_index=873270] store_id=2138 n_dt_files=10 cost=3.706s"] [source="keyspace=1 table_id=2684"] [thread_id=209]
[2024/04/25 07:56:01.506 +00:00] [INFO] [ApplySnapshot.cpp:319] ["Begin apply snapshot, new_region=[region_id=2953 applied_term=6 applied_index=873270]"] [thread_id=208]
[2024/04/25 07:56:01.506 +00:00] [INFO] [ApplySnapshot.cpp:78] ["[region_id=2953 applied_term=6 applied_index=812909] set state to `Applying`"] [thread_id=208]
[2024/04/25 07:56:01.506 +00:00] [INFO] [KVStore.cpp:398] ["Start to persist [region_id=2953 applied_term=6 applied_index=812909], cache size: 0 bytes for `save previous region before apply `"] [thread_id=208]
[2024/04/25 07:56:01.507 +00:00] [INFO] [CheckpointIngestInfo.cpp:276] ["Erase CheckpointIngestInfo from disk by force, region_id=2953 exist=false in_memory=false reason=ResolveStateApplySnapshot"] [thread_id=208]
[2024/04/25 07:56:01.698 +00:00] [INFO] [RegionTable.cpp:437] ["internal region has larger range, keyspace=1 table_id=2684 region_id=2953"] [thread_id=208]
[2024/04/25 07:56:01.698 +00:00] [INFO] [KVStore.cpp:398] ["Start to persist [region_id=2953 applied_term=6 applied_index=873270], cache size: 0 bytes for `save current region after apply `"] [thread_id=208]
[2024/04/25 07:56:01.699 +00:00] [INFO] [ApplySnapshot.cpp:332] ["Finish apply snapshot, cost=0.192s region_id=2953"] [thread_id=208]
[2024/04/25 07:56:02.045 +00:00] [INFO] [SSTFilesToBlockInputStream.cpp:129] ["Finish Construct MultiSSTReader, write=1 lock=1 default=0 region_id=2953 snapshot_index=939445"] [source="keyspace=1 table_id=2684"] [thread_id=236]
[2024/04/25 07:56:02.045 +00:00] [INFO] [PrehandleSnapshot.cpp:644] ["Single threaded prehandling for single big region, range=[7800000174800000FF0000000A7C5F7280FF0000001183204200FE,7800000174800000FF0000000A7C5F72FFFFFFFFFFFFFFFFFF00FF0000000000000000F7], region_id=2953"] [thread_id=236]
[2024/04/25 07:56:05.370 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=939445] file_idx=0 file_rows=1005140 file_bytes=95488300 data_range=[293806146,294805680) file_bytes_on_disk=35591262 file=/data0/db/data/ks_1_t_2684/stable/dmf_3501"] [source="keyspace=1 table_id=2684"] [thread_id=236]
[2024/04/25 07:56:09.093 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=939445] file_idx=1 file_rows=1004329 file_bytes=95411255 data_range=[294805680,295804375) file_bytes_on_disk=35779676 file=/data0/db/data/ks_1_t_2684/stable/dmf_3502"] [source="keyspace=1 table_id=2684"] [thread_id=236]
[2024/04/25 07:56:12.729 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=939445] file_idx=2 file_rows=1005425 file_bytes=95515375 data_range=[295804375,296803121) file_bytes_on_disk=35692514 file=/data0/db/data/ks_1_t_2684/stable/dmf_3503"] [source="keyspace=1 table_id=2684"] [thread_id=236]
[2024/04/25 07:56:15.815 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=939445] file_idx=3 file_rows=1004977 file_bytes=95472815 data_range=[296803121,297802528) file_bytes_on_disk=35732331 file=/data0/db/data/ks_1_t_2684/stable/dmf_3504"] [source="keyspace=1 table_id=2684"] [thread_id=236]
[2024/04/25 07:56:18.521 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=939445] file_idx=4 file_rows=1004990 file_bytes=95474050 data_range=[297802528,298802421) file_bytes_on_disk=35663885 file=/data0/db/data/ks_1_t_2684/stable/dmf_3505"] [source="keyspace=1 table_id=2684"] [thread_id=236]
[2024/04/25 07:56:21.488 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=939445] file_idx=5 file_rows=1005010 file_bytes=95475950 data_range=[298802421,299802412) file_bytes_on_disk=35791393 file=/data0/db/data/ks_1_t_2684/stable/dmf_3506"] [source="keyspace=1 table_id=2684"] [thread_id=236]
[2024/04/25 07:56:24.691 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=939445] file_idx=6 file_rows=1006436 file_bytes=95611420 data_range=[299802412,300996105) file_bytes_on_disk=40031794 file=/data0/db/data/ks_1_t_2684/stable/dmf_3507"] [source="keyspace=1 table_id=2684"] [thread_id=236]
[2024/04/25 07:56:27.776 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=939445] file_idx=7 file_rows=1007616 file_bytes=95723520 data_range=[300996105,302003866) file_bytes_on_disk=43279341 file=/data0/db/data/ks_1_t_2684/stable/dmf_3508"] [source="keyspace=1 table_id=2684"] [thread_id=236]
[2024/04/25 07:56:30.652 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=939445] file_idx=8 file_rows=1007616 file_bytes=95723520 data_range=[302003866,303011613) file_bytes_on_disk=43301003 file=/data0/db/data/ks_1_t_2684/stable/dmf_3509"] [source="keyspace=1 table_id=2684"] [thread_id=236]
[2024/04/25 07:56:32.344 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=939445] file_idx=9 file_rows=526360 file_bytes=50004200 data_range=[303011613,303539073) file_bytes_on_disk=22629934 file=/data0/db/data/ks_1_t_2684/stable/dmf_3510"] [source="keyspace=1 table_id=2684"] [thread_id=236]
[2024/04/25 07:56:32.344 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:130] ["Transformed snapshot in SSTFile to DTFiles, region=[region_id=2953 applied_term=6 applied_index=939445] job_type=ApplySnapshot cost_ms=30298 rows=9577899 bytes=909900405 bytes_on_disk=363493133 write_cf_keys=9594904 default_cf_keys=0 lock_cf_keys=54 splid_id=18446744073709551615 dt_files=[files_num=10 dmf_3501,dmf_3502,dmf_3503,dmf_3504,dmf_3505,dmf_3506,dmf_3507,dmf_3508,dmf_3509,dmf_3510]"] [source="keyspace=1 table_id=2684"] [thread_id=236]
[2024/04/25 07:56:35.865 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:156] ["Upload snapshot DTFiles done, region=[region_id=2953 applied_term=6 applied_index=939445] store_id=2138 n_dt_files=10 cost=3.522s"] [source="keyspace=1 table_id=2684"] [thread_id=236]
[2024/04/25 07:56:35.866 +00:00] [INFO] [ApplySnapshot.cpp:319] ["Begin apply snapshot, new_region=[region_id=2953 applied_term=6 applied_index=939445]"] [thread_id=208]
[2024/04/25 07:56:35.866 +00:00] [INFO] [ApplySnapshot.cpp:78] ["[region_id=2953 applied_term=6 applied_index=874172] set state to `Applying`"] [thread_id=208]
[2024/04/25 07:56:35.872 +00:00] [INFO] [KVStore.cpp:398] ["Start to persist [region_id=2953 applied_term=6 applied_index=874172], cache size: 0 bytes for `save previous region before apply `"] [thread_id=208]
[2024/04/25 07:56:35.872 +00:00] [INFO] [CheckpointIngestInfo.cpp:276] ["Erase CheckpointIngestInfo from disk by force, region_id=2953 exist=false in_memory=false reason=ResolveStateApplySnapshot"] [thread_id=208]
[2024/04/25 07:56:36.120 +00:00] [INFO] [RegionTable.cpp:437] ["internal region has larger range, keyspace=1 table_id=2684 region_id=2953"] [thread_id=208]
[2024/04/25 07:56:36.120 +00:00] [INFO] [KVStore.cpp:398] ["Start to persist [region_id=2953 applied_term=6 applied_index=939445], cache size: 0 bytes for `save current region after apply `"] [thread_id=208]
[2024/04/25 07:56:36.121 +00:00] [INFO] [ApplySnapshot.cpp:332] ["Finish apply snapshot, cost=0.255s region_id=2953"] [thread_id=208]
[2024/04/25 07:56:36.134 +00:00] [INFO] [KVStore.cpp:577] ["[region_id=2953] flush region due to tryFlushRegionData, index 939663 term 6 truncated_index 0 truncated_term 0 gap 218/200"] [thread_id=227]
[2024/04/25 07:56:36.136 +00:00] [INFO] [KVStore.cpp:398] ["Start to persist [region_id=2953 applied_term=6 applied_index=939664], cache size: 0 bytes for `tryFlushRegionData `"] [thread_id=227]
[2024/04/25 07:56:36.554 +00:00] [INFO] [SSTFilesToBlockInputStream.cpp:129] ["Finish Construct MultiSSTReader, write=1 lock=1 default=0 region_id=2953 snapshot_index=1004232"] [source="keyspace=1 table_id=2684"] [thread_id=209]
[2024/04/25 07:56:36.554 +00:00] [INFO] [PrehandleSnapshot.cpp:644] ["Single threaded prehandling for single big region, range=[7800000174800000FF0000000A7C5F7280FF0000001183204200FE,7800000174800000FF0000000A7C5F72FFFFFFFFFFFFFFFFFF00FF0000000000000000F7], region_id=2953"] [thread_id=209]
[2024/04/25 07:56:40.952 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=1004232] file_idx=0 file_rows=1005140 file_bytes=95488300 data_range=[293806146,294804853) file_bytes_on_disk=35579846 file=/data0/db/data/ks_1_t_2684/stable/dmf_3567"] [source="keyspace=1 table_id=2684"] [thread_id=209]
[2024/04/25 07:56:44.299 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=1004232] file_idx=1 file_rows=1004329 file_bytes=95411255 data_range=[294804853,295802603) file_bytes_on_disk=35770964 file=/data0/db/data/ks_1_t_2684/stable/dmf_3571"] [source="keyspace=1 table_id=2684"] [thread_id=209]
[2024/04/25 07:56:46.877 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=1004232] file_idx=2 file_rows=1005425 file_bytes=95515375 data_range=[295802603,296800592) file_bytes_on_disk=35715728 file=/data0/db/data/ks_1_t_2684/stable/dmf_3582"] [source="keyspace=1 table_id=2684"] [thread_id=209]
[2024/04/25 07:56:49.578 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=1004232] file_idx=3 file_rows=1004977 file_bytes=95472815 data_range=[296800592,297799285) file_bytes_on_disk=35731568 file=/data0/db/data/ks_1_t_2684/stable/dmf_3588"] [source="keyspace=1 table_id=2684"] [thread_id=209]
[2024/04/25 07:56:52.102 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=1004232] file_idx=4 file_rows=1004990 file_bytes=95474050 data_range=[297799285,298798567) file_bytes_on_disk=35667756 file=/data0/db/data/ks_1_t_2684/stable/dmf_3592"] [source="keyspace=1 table_id=2684"] [thread_id=209]
[2024/04/25 07:56:54.726 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=1004232] file_idx=5 file_rows=1005010 file_bytes=95475950 data_range=[298798567,299797697) file_bytes_on_disk=35779119 file=/data0/db/data/ks_1_t_2684/stable/dmf_3596"] [source="keyspace=1 table_id=2684"] [thread_id=209]
[2024/04/25 07:56:57.525 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=1004232] file_idx=6 file_rows=1006436 file_bytes=95611420 data_range=[299797697,300991119) file_bytes_on_disk=39990039 file=/data0/db/data/ks_1_t_2684/stable/dmf_3601"] [source="keyspace=1 table_id=2684"] [thread_id=209]
[2024/04/25 07:57:00.378 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=1004232] file_idx=7 file_rows=1007616 file_bytes=95723520 data_range=[300991119,301998880) file_bytes_on_disk=43278427 file=/data0/db/data/ks_1_t_2684/stable/dmf_3605"] [source="keyspace=1 table_id=2684"] [thread_id=209]
[2024/04/25 07:57:02.949 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=1004232] file_idx=8 file_rows=1007616 file_bytes=95723520 data_range=[301998880,303006627) file_bytes_on_disk=43301592 file=/data0/db/data/ks_1_t_2684/stable/dmf_3612"] [source="keyspace=1 table_id=2684"] [thread_id=209]
[2024/04/25 07:57:04.883 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:237] ["Finished writing DTFile from snapshot data, region=[region_id=2953 applied_term=6 applied_index=1004232] file_idx=9 file_rows=746330 file_bytes=70901350 data_range=[303006627,303768647) file_bytes_on_disk=32084694 file=/data0/db/data/ks_1_t_2684/stable/dmf_3620"] [source="keyspace=1 table_id=2684"] [thread_id=209]
[2024/04/25 07:57:04.884 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:130] ["Transformed snapshot in SSTFile to DTFiles, region=[region_id=2953 applied_term=6 applied_index=1004232] job_type=ApplySnapshot cost_ms=28329 rows=9797869 bytes=930797555 bytes_on_disk=372899733 write_cf_keys=9814874 default_cf_keys=0 lock_cf_keys=80 splid_id=18446744073709551615 dt_files=[files_num=10 dmf_3567,dmf_3571,dmf_3582,dmf_3588,dmf_3592,dmf_3596,dmf_3601,dmf_3605,dmf_3612,dmf_3620]"] [source="keyspace=1 table_id=2684"] [thread_id=209]
[2024/04/25 07:57:08.434 +00:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:156] ["Upload snapshot DTFiles done, region=[region_id=2953 applied_term=6 applied_index=1004232] store_id=2138 n_dt_files=10 cost=3.550s"] [source="keyspace=1 table_id=2684"] [thread_id=209]
[2024/04/25 07:57:08.434 +00:00] [INFO] [ApplySnapshot.cpp:319] ["Begin apply snapshot, new_region=[region_id=2953 applied_term=6 applied_index=1004232]"] [thread_id=208]
[2024/04/25 07:57:08.434 +00:00] [INFO] [ApplySnapshot.cpp:78] ["[region_id=2953 applied_term=6 applied_index=940367] set state to `Applying`"] [thread_id=208]
[2024/04/25 07:57:08.434 +00:00] [INFO] [KVStore.cpp:398] ["Start to persist [region_id=2953 applied_term=6 applied_index=940367], cache size: 0 bytes for `save previous region before apply `"] [thread_id=208]
[2024/04/25 07:57:08.435 +00:00] [INFO] [CheckpointIngestInfo.cpp:276] ["Erase CheckpointIngestInfo from disk by force, region_id=2953 exist=false in_memory=false reason=ResolveStateApplySnapshot"] [thread_id=208]
[2024/04/25 07:57:08.649 +00:00] [INFO] [RegionTable.cpp:437] ["internal region has larger range, keyspace=1 table_id=2684 region_id=2953"] [thread_id=208]
[2024/04/25 07:57:08.649 +00:00] [INFO] [KVStore.cpp:398] ["Start to persist [region_id=2953 applied_term=6 applied_index=1004232], cache size: 0 bytes for `save current region after apply `"] [thread_id=208]
[2024/04/25 07:57:08.649 +00:00] [INFO] [ApplySnapshot.cpp:332] ["Finish apply snapshot, cost=0.215s region_id=2953"] [thread_id=208]
[2024/04/25 07:57:09.530 +00:00] [INFO] [KVStore.cpp:577] ["[region_id=2953] flush region due to tryFlushRegionData, index 1033328 term 6 truncated_index 0 truncated_term 0 gap 29096/200"] [thread_id=228]
[2024/04/25 07:57:09.536 +00:00] [INFO] [KVStore.cpp:398] ["Start to persist [region_id=2953 applied_term=6 applied_index=1033329], cache size: 0 bytes for `tryFlushRegionData `"] [thread_id=228]
[2024/04/25 07:57:09.543 +00:00] [INFO] [RaftCommands.cpp:244] ["[region_id=2953 applied_term=6 applied_index=1033331] execute admin command ChangePeerV2 at [term: 6, index: 1033332]"] [thread_id=228]
[2024/04/25 07:57:09.543 +00:00] [INFO] [RaftCommands.cpp:72] ["[region_id=2953] execute change peer cmd: changes { change_type: RemoveNode peer { id: 32608 store_id: 2138 role: Learner } }"] [thread_id=228]
[2024/04/25 07:57:09.543 +00:00] [INFO] [RaftCommands.cpp:74] ["After execute change peer cmd, current region info: [region_id=2953 index=1033332 table_id=2684 ver=85 conf_ver=9 state=Tombstone peer=id: 32608 store_id: 2138 role: Learner]"] [thread_id=228]
[2024/04/25 07:57:09.543 +00:00] [INFO] [KVStore.cpp:258] ["Start to remove region_id=2953"] [thread_id=228]
[2024/04/25 07:57:09.543 +00:00] [INFO] [KVStore.cpp:281] ["Persisted region_id=2953 deleted"] [thread_id=228]
[2024/04/25 07:57:09.543 +00:00] [INFO] [RegionTable.cpp:240] ["remove region in RegionTable done, region_id=2953"] [thread_id=228]
[2024/04/25 07:57:09.548 +00:00] [INFO] [RegionTable.cpp:252] ["remove region in storage done, region_id=2953"] [thread_id=228]
[2024/04/25 07:57:09.548 +00:00] [INFO] [KVStore.cpp:285] ["Remove region_id=2953 done"] [thread_id=228]
[2024/04/25 07:57:09.587 +00:00] [INFO] [CheckpointIngestInfo.cpp:276] ["Erase CheckpointIngestInfo from disk by force, region_id=2953 exist=false in_memory=false reason=ResolveStateDestroy"] [thread_id=211]
[2024/04/25 07:57:09.587 +00:00] [INFO] [KVStore.cpp:352] ["region_id=2953 not found, might be removed already"] [thread_id=211]
[root@tc-tiflash-0 logs]# cat tiflash_tikv*.log | grep "region_id=2953" | grep "snapshot" | grep "07:43"
[2024/04/25 07:43:00.055 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:00.500 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:01.077 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:02.108 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:02.496 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:03.174 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:04.226 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:05.163 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:06.138 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:06.562 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:07.114 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:08.054 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:08.486 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:09.054 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:10.118 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:10.504 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:11.060 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:12.060 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:12.447 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:13.062 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:14.062 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:14.447 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:15.064 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:16.100 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:16.447 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:17.066 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:18.071 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:18.468 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:19.280 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:20.295 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:20.678 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:21.297 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:22.404 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:24.307 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:24.707 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:25.471 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:28.570 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:28.853 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:29.374 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:30.188 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:30.460 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:31.158 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:32.131 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:32.450 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:33.133 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:34.101 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:34.451 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:35.214 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:36.105 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:36.448 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:37.195 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:38.152 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:38.538 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:40.112 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:40.447 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:41.118 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:42.115 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:42.455 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:43.116 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:44.118 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:44.449 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:45.120 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:46.120 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:46.448 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:47.121 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:48.122 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:48.449 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:49.134 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:50.126 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:50.448 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:51.136 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:52.130 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:52.451 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:53.131 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:54.132 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:54.448 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:55.134 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:56.135 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:56.448 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:57.136 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:57.925 +00:00] [INFO] [snapshot.rs:79] ["pre apply snapshot"] [pending=0] [snap_key="SnapKey { region_id: 2953, term: 6, idx: 69106 }"] [region_id=2953] [peer_id=32608]
[2024/04/25 07:43:57.925 +00:00] [INFO] [fap_snapshot.rs:123] ["fast path: start applying first fap snapshot 2138:2953 32608"] [region_id=2953] [snap_key="SnapKey { region_id: 2953, term: 6, idx: 69106 }"]
[2024/04/25 07:43:57.925 +00:00] [INFO] [fap_snapshot.rs:149] ["fast path: fap snapshot mismatch/nonexist 2138:2953 32608"] [tag="pre check"] [current_enabled=true] [cost_total=269006] [cost_snapshot=1714031037925] [region_id=2953] [snap_key="SnapKey { region_id: 2953, term: 6, idx: 69106 }"]
[2024/04/25 07:43:57.925 +00:00] [INFO] [snapshot.rs:172] ["post apply snapshot"] [pending=1] [region="id: 2953 start_key: 7800000174800000FF0000000A7C5F7280FF0000001183204200FE end_key: 7800000174800000FF0000000A7C5F72FFFFFFFFFFFFFFFFFF00FF0000000000000000F7 region_epoch { conf_ver: 8 version: 85 } peers { id: 2954 store_id: 1 } peers { id: 2955 store_id: 4 } peers { id: 2956 store_id: 53 } peers { id: 2957 store_id: 2137 role: Learner } peers { id: 2971 store_id: 2163 role: Learner } peers { id: 32608 store_id: 2138 role: Learner }"] [region_id=2953] [snap_key="SnapKey { region_id: 2953, term: 6, idx: 69106 }"] [peer_id=32608]
[2024/04/25 07:43:58.148 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:58.448 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[2024/04/25 07:43:59.139 +00:00] [DEBUG] [peer.rs:2583] ["still applying snapshot, skip further handling"] [peer_id=32608] [region_id=2953]
[root@tc-tiflash-0 logs]#

[2024/04/25 07:39:51.824 +00:00] [ERROR] [Exception.cpp:96] ["Failed when try to restore from checkpoint region_id=2953 new_peer_id=32608 deadline exceed, <key=<s2163/data/ks_1_t_2684/dmf_2370,2138,30>,type=AddLock>: Code: 159, e.displayText() = DB::Exception: deadline exceed, <key=<s2163/data/ks_1_t_2684/dmf_2370,2138,30>,type=AddLock>, e.what() = DB::Exception, Stack trace:
       0x1f94c30\tDB::Exception::Exception<>(int, std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&) [tiflash+33115184]
                \tdbms/src/Common/Exception.h:53
       0x8a8a659\tDB::S3::S3LockClient::sendTryAddLockRequest(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, unsigned int, unsigned int, long) [tiflash+145270361]
                \tdbms/src/Flash/Disaggregated/S3LockClient.cpp:62
       0x86e42f0\tDB::PS::V3::S3LockLocalManager::createS3LockForWriteBatch(DB::UniversalWriteBatch&) [tiflash+141443824]
                \tdbms/src/Storages/Page/V3/Universal/S3LockLocalManager.cpp:173
       0x86d9139\tDB::UniversalPageStorage::write(DB::UniversalWriteBatch&&, DB::PS::V3::PageType, std::__1::shared_ptr<DB::WriteLimiter> const&) const [tiflash+141398329]
                \tdbms/src/Storages/Page/V3/Universal/UniversalPageStorage.cpp:118
       0x865758c\tDB::PageWriter::write(DB::WriteBatchWrapper&&, std::__1::shared_ptr<DB::WriteLimiter>) const [tiflash+140866956]
                \tdbms/src/Storages/Page/PageStorage.cpp:621
       0x7536c63\tDB::DM::WriteBatches::writeLogAndData() [tiflash+122907747]
                \tdbms/src/Storages/DeltaMerge/WriteBatchesImpl.h:146
       0x762a215\tDB::DM::StableValueSpace::createFromCheckpoint(std::__1::shared_ptr<DB::Logger> const&, DB::DM::DMContext&, std::__1::shared_ptr<DB::UniversalPageStorage>, unsigned long, DB::DM::WriteBatches&) [tiflash+123904533]
                \tdbms/src/Storages/DeltaMerge/StableValueSpace.cpp:224
       0x75a18e2\tDB::DM::Segment::createTargetSegmentsFromCheckpoint(std::__1::shared_ptr<DB::Logger> const&, DB::DM::DMContext&, unsigned long, std::__1::vector<DB::DM::Segment::SegmentMetaInfo, std::__1::allocator<DB::DM::Segment::SegmentMetaInfo> > const&, DB::DM::RowKeyRange const&, std::__1::shared_ptr<DB::UniversalPageStorage>, DB::DM::WriteBatches&) [tiflash+123345122]
                \tdbms/src/Storages/DeltaMerge/Segment.cpp:488
       0x758de06\tDB::DM::DeltaMergeStore::buildSegmentsFromCheckpointInfo(std::__1::shared_ptr<DB::DM::DMContext> const&, DB::DM::RowKeyRange const&, std::__1::shared_ptr<DB::CheckpointInfo> const&) const [tiflash+123264518]
                \tdbms/src/Storages/DeltaMerge/DeltaMergeStore_Ingest.cpp:1132
       0x8089a6a\tDB::DM::DeltaMergeStore::buildSegmentsFromCheckpointInfo(DB::Context const&, DB::Settings const&, DB::DM::RowKeyRange const&, std::__1::shared_ptr<DB::CheckpointInfo> const&) [tiflash+134781546]
                \tdbms/src/Storages/DeltaMerge/DeltaMergeStore.h:357
       0x8b1f38e\tstd::__1::__function::__func<FastAddPeer::$_29, std::__1::allocator<FastAddPeer::$_29>, DB::FastAddPeerRes ()>::operator()() [tiflash+145879950]
                \t/usr/local/bin/../include/c++/v1/__functional/function.h:345
       0x8b1e411\tstd::__1::__function::__func<DB::AsyncTasks<unsigned long, std::__1::function<DB::FastAddPeerRes ()>, DB::FastAddPeerRes>::addTaskWithCancel(unsigned long, std::__1::function<DB::FastAddPeerRes ()>, std::__1::function<void ()>)::'lambda'(), std::__1::allocator<DB::AsyncTasks<unsigned long, std::__1::function<DB::FastAddPeerRes ()>, DB::FastAddPeerRes>::addTaskWithCancel(unsigned long, std::__1::function<DB::FastAddPeerRes ()>, std::__1::function<void ()>)::'lambda'()>, void ()>::operator()() [tiflash+145875985]
                \t/usr/local/bin/../include/c++/v1/__functional/function.h:345
       0x1fb4d07\tDB::ThreadPoolImpl<DB::ThreadFromGlobalPoolImpl<false> >::worker(std::__1::__list_iterator<DB::ThreadFromGlobalPoolImpl<false>, void*>) [tiflash+33246471]
                \tdbms/src/Common/UniThreadPool.cpp:306
       0x1fb6fa3\tstd::__1::__function::__func<DB::ThreadFromGlobalPoolImpl<false>::ThreadFromGlobalPoolImpl<bool DB::ThreadPoolImpl<DB::ThreadFromGlobalPoolImpl<false> >::scheduleImpl<bool>(std::__1::function<void ()>, long, std::__1::optional<unsigned long>, bool)::'lambda0'()>(bool&&)::'lambda'(), std::__1::allocator<DB::ThreadFromGlobalPoolImpl<false>::ThreadFromGlobalPoolImpl<bool DB::ThreadPoolImpl<DB::ThreadFromGlobalPoolImpl<false> >::scheduleImpl<bool>(std::__1::function<void ()>, long, std::__1::optional<unsigned long>, bool)::'lambda0'()>(bool&&)::'lambda'()>, void ()>::operator()() [tiflash+33255331]
                \t/usr/local/bin/../include/c++/v1/__functional/function.h:345
       0x1fb5de8\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::ThreadPoolImpl<std::__1::thread>::scheduleImpl<void>(std::__1::function<void ()>, long, std::__1::optional<unsigned long>, bool)::'lambda0'()> >(void*) [tiflash+33250792]
                \t/usr/local/bin/../include/c++/v1/thread:291
  0x7f9449970ea5\tstart_thread [libpthread.so.0+32421]
  0x7f944927f96d\t__clone [libc.so.6+1042797]"] [source=FastAddPeerImpl] [thread_id=34]

[2024/04/25 07:44:28.077 +00:00] [FATAL] [Exception.cpp:106] ["Code: 49, e.displayText() = DB::Exception: Check prev_state == FAPAsyncTasks::TaskState::NotScheduled failed: FastAddPeer: find scheduled fap task, region_id=2953 fap_state=Finished is_regular_snapshot=true: (while applyPreHandledSnapshot region_id=2953), e.what() = DB::Exception, Stack trace:
       0x1ecba7e\tDB::Exception::Exception(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, int) [tiflash+32291454]
                \tdbms/src/Common/Exception.h:46
       0x8b3547a\tDB::FastAddPeerContext::resolveFapSnapshotState(DB::TMTContext&, DB::TiFlashRaftProxyHelper const*, unsigned long, bool) [tiflash+145970298]
                \tdbms/src/Storages/KVStore/MultiRaft/Disagg/FastAddPeerContext.cpp:245
       0x8aa7854\tvoid DB::KVStore::checkAndApplyPreHandledSnapshot<DB::RegionPtrWithSnapshotFiles>(DB::RegionPtrWithSnapshotFiles const&, DB::TMTContext&) [tiflash+145389652]
                \tdbms/src/Storages/KVStore/MultiRaft/ApplySnapshot.cpp:128
       0x8aa66d0\tvoid DB::KVStore::applyPreHandledSnapshot<DB::RegionPtrWithSnapshotFiles>(DB::RegionPtrWithSnapshotFiles const&, DB::TMTContext&) [tiflash+145385168]
                \tdbms/src/Storages/KVStore/MultiRaft/ApplySnapshot.cpp:327
       0x8a9910a\tApplyPreHandledSnapshot [tiflash+145330442]
                \tdbms/src/Storages/KVStore/FFI/ProxyFFI.cpp:693
  0x7f944b98effc\t_$LT$engine_store_ffi..observer..TiFlashObserver$LT$T$C$ER$GT$$u20$as$u20$raftstore..coprocessor..ApplySnapshotObserver$GT$::post_apply_snapshot::h427945d65ce188cf [libtiflash_proxy.so+26214396]
  0x7f944c915649\traftstore::store::worker::region::Runner$LT$EK$C$R$C$T$GT$::handle_pending_applies::hab871494553185a2 [libtiflash_proxy.so+42493513]
  0x7f944bf7d1df\tyatp::task::future::RawTask$LT$F$GT$::poll::hf33305e587d2c9fd [libtiflash_proxy.so+32432607]
  0x7f944d86dd7b\t_$LT$yatp..task..future..Runner$u20$as$u20$yatp..pool..runner..Runner$GT$::handle::h3c8ad78cdc484f59 [libtiflash_proxy.so+58584443]
  0x7f944baa5fc4\tstd::sys_common::backtrace::__rust_begin_short_backtrace::h37aa3ec1d0c1d3f0 [libtiflash_proxy.so+27357124]
  0x7f944baeb388\tcore::ops::function::FnOnce::call_once$u7b$$u7b$vtable.shim$u7d$$u7d$::h70659c9e4b989e59 [libtiflash_proxy.so+27640712]
  0x7f944cf98525\tstd::sys::unix::thread::Thread::new::thread_start::hd2791a9cabec1fda [libtiflash_proxy.so+49321253]
                \t/rustc/96ddd32c4bfb1d78f0cd03eb068b1710a8cebeef/library/std/src/sys/unix/thread.rs:108
  0x7f9449970ea5\tstart_thread [libpthread.so.0+32421]
  0x7f944927f96d\t__clone [libc.so.6+1042797]"] [source="void DB::ApplyPreHandledSnapshot(DB::EngineStoreServerWrap *, DB::RawVoidPtr, DB::RawCppPtrType)"] [thread_id=23]

1. Minimal reproduce step (Required)

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

3. What did you see instead (Required)

4. What is your TiFlash version? (Required)