flaky test DMStoreForSegmentReadTaskTest.DisaggReadSnapshot #10612
Description
Bug Report
Please answer these questions before submitting your issue. Thanks!
1. Minimal reproduce step (Required)
2. What did you expect to see? (Required)
[m�[0;32m[==========] �[mRunning 1 test from 1 test case.
�[0;32m[----------] �[mGlobal test environment set-up.
�[0;32m[----------] �[m1 test from DMStoreForSegmentReadTaskTest
�[0;32m[ RUN ] �[mDMStoreForSegmentReadTaskTest.DisaggReadSnapshot
[2025/12/11 22:26:35.517 +08:00] [WARN] [Context.cpp:1670] ["GlobalStoragePool has already been initialized."] [source=Context] [thread_id=1]
[2025/12/11 22:26:35.517 +08:00] [INFO] [PageStorageImpl.cpp:54] ["PageStorageImpl start. Config{ PageStorageConfig {blob_file_limit_size: 268435456, blob_spacemap_type: 2, blob_heavy_gc_valid_rate: 0.500, blob_heavy_gc_valid_rate_raft_data: 0.050, blob_block_alignment_bytes: 0, wal_roll_size: 2097152, wal_max_persisted_log_files: 4} }"] [source=__global__.log] [thread_id=1]
[2025/12/11 22:26:35.517 +08:00] [INFO] [PageStorageImpl.cpp:54] ["PageStorageImpl start. Config{ PageStorageConfig {blob_file_limit_size: 268435456, blob_spacemap_type: 2, blob_heavy_gc_valid_rate: 0.500, blob_heavy_gc_valid_rate_raft_data: 0.050, blob_block_alignment_bytes: 0, wal_roll_size: 2097152, wal_max_persisted_log_files: 4} }"] [source=__global__.data] [thread_id=1]
[2025/12/11 22:26:35.517 +08:00] [INFO] [PageStorageImpl.cpp:54] ["PageStorageImpl start. Config{ PageStorageConfig {blob_file_limit_size: 268435456, blob_spacemap_type: 2, blob_heavy_gc_valid_rate: 0.500, blob_heavy_gc_valid_rate_raft_data: 0.050, blob_block_alignment_bytes: 0, wal_roll_size: 2097152, wal_max_persisted_log_files: 4} }"] [source=__global__.meta] [thread_id=1]
[2025/12/11 22:26:35.518 +08:00] [INFO] [PageDirectoryFactory.cpp:68] ["PageDirectory restored, max_page_id=0 max_applied_ver=0"] [source=__global__.log] [thread_id=1]
[2025/12/11 22:26:35.518 +08:00] [INFO] [PageDirectoryFactory.cpp:68] ["PageDirectory restored, max_page_id=0 max_applied_ver=0"] [source=__global__.data] [thread_id=1]
[2025/12/11 22:26:35.518 +08:00] [INFO] [PageDirectoryFactory.cpp:68] ["PageDirectory restored, max_page_id=0 max_applied_ver=0"] [source=__global__.meta] [thread_id=1]
[2025/12/11 22:26:35.519 +08:00] [WARN] [Context.cpp:1670] ["GlobalStoragePool has already been initialized."] [source=Context] [thread_id=1]
[2025/12/11 22:26:35.519 +08:00] [INFO] [PageStorageImpl.cpp:54] ["PageStorageImpl start. Config{ PageStorageConfig {blob_file_limit_size: 268435456, blob_spacemap_type: 2, blob_heavy_gc_valid_rate: 0.500, blob_heavy_gc_valid_rate_raft_data: 0.050, blob_block_alignment_bytes: 0, wal_roll_size: 2097152, wal_max_persisted_log_files: 4} }"] [source=__global__.log] [thread_id=1]
[2025/12/11 22:26:35.519 +08:00] [INFO] [PageStorageImpl.cpp:54] ["PageStorageImpl start. Config{ PageStorageConfig {blob_file_limit_size: 268435456, blob_spacemap_type: 2, blob_heavy_gc_valid_rate: 0.500, blob_heavy_gc_valid_rate_raft_data: 0.050, blob_block_alignment_bytes: 0, wal_roll_size: 2097152, wal_max_persisted_log_files: 4} }"] [source=__global__.data] [thread_id=1]
[2025/12/11 22:26:35.519 +08:00] [INFO] [PageStorageImpl.cpp:54] ["PageStorageImpl start. Config{ PageStorageConfig {blob_file_limit_size: 268435456, blob_spacemap_type: 2, blob_heavy_gc_valid_rate: 0.500, blob_heavy_gc_valid_rate_raft_data: 0.050, blob_block_alignment_bytes: 0, wal_roll_size: 2097152, wal_max_persisted_log_files: 4} }"] [source=__global__.meta] [thread_id=1]
[2025/12/11 22:26:35.520 +08:00] [INFO] [BlobStore.cpp:130] ["Ignore not blob file, dir=/tmp-memfs/tiflash-tests/tmp/DMStoreForSegmentReadTaskTest.DisaggReadSnapshot/page/log file=wal err_msg="] [source=__global__.log] [thread_id=1]
[2025/12/11 22:26:35.520 +08:00] [INFO] [PageDirectoryFactory.cpp:68] ["PageDirectory restored, max_page_id=0 max_applied_ver=0"] [source=__global__.log] [thread_id=1]
[2025/12/11 22:26:35.520 +08:00] [INFO] [BlobStore.cpp:130] ["Ignore not blob file, dir=/tmp-memfs/tiflash-tests/tmp/DMStoreForSegmentReadTaskTest.DisaggReadSnapshot/page/data file=wal err_msg="] [source=__global__.data] [thread_id=1]
[2025/12/11 22:26:35.520 +08:00] [INFO] [PageDirectoryFactory.cpp:68] ["PageDirectory restored, max_page_id=0 max_applied_ver=0"] [source=__global__.data] [thread_id=1]
[2025/12/11 22:26:35.521 +08:00] [INFO] [BlobStore.cpp:130] ["Ignore not blob file, dir=/tmp-memfs/tiflash-tests/tmp/DMStoreForSegmentReadTaskTest.DisaggReadSnapshot/page/meta file=wal err_msg="] [source=__global__.meta] [thread_id=1]
[2025/12/11 22:26:35.521 +08:00] [INFO] [PageDirectoryFactory.cpp:68] ["PageDirectory restored, max_page_id=0 max_applied_ver=0"] [source=__global__.meta] [thread_id=1]
[2025/12/11 22:26:35.522 +08:00] [INFO] [DeltaMergeStore.cpp:290] ["Restore DeltaMerge Store start"] [source="keyspace=4294967295 table_id=100"] [thread_id=1]
[2025/12/11 22:26:35.522 +08:00] [DEBUG] [DeltaMergeStore.cpp:2179] ["Loading dt files"] [source="keyspace=4294967295 table_id=100"] [thread_id=1]
[2025/12/11 22:26:35.522 +08:00] [INFO] [StoragePool.cpp:720] ["Finished StoragePool restore. run_mode=ONLY_V3 keyspace=4294967295 table_id=100 max_log_page_id=0 max_data_page_id=0 max_meta_page_id=1"] [source=test.t_100] [thread_id=1]
[2025/12/11 22:26:35.522 +08:00] [INFO] [DeltaMergeStore.cpp:365] ["Restore DeltaMerge Store end, ps_run_mode=ONLY_V3"] [source="keyspace=4294967295 table_id=100"] [thread_id=1]
[2025/12/11 22:26:35.523 +08:00] [INFO] [Disagg.cpp:49] ["Local cache directory will be cleared before setting up LocalPageCache"] [thread_id=1]
[2025/12/11 22:26:35.524 +08:00] [INFO] [Disagg.cpp:66] ["Initialize Read Node page cache in cache directory. path=/tmp-memfs/tiflash-tests/tmp/DMStoreForSegmentReadTaskTest.DisaggReadSnapshot capacity=1073741824"] [thread_id=1]
[2025/12/11 22:26:35.525 +08:00] [INFO] [PageDirectoryFactory.cpp:68] ["PageDirectory restored, max_page_id=0 max_applied_ver=0"] [source=read_cache] [thread_id=1]
[2025/12/11 22:26:35.525 +08:00] [DEBUG] [BlobStore.cpp:1337] ["BlobStore gc get status done. details {ReadOnly: [null]} {Unchanged: [null]} {FullGC: [null]} {Truncated: [null]}"] [source=read_cache] [thread_id=6]
[2025/12/11 22:26:35.525 +08:00] [DEBUG] [GCDefines.cpp:154] ["GC finished without full gc. [total time=0ms] [compact wal=0ms] [compact directory=0ms] [compact spacemap=0ms] [gc status=0ms] [gc entries=0ms] [gc data=0ms] [gc apply=0ms]"] [source=read_cache] [thread_id=6]
[2025/12/11 22:26:35.525 +08:00] [DEBUG] [RNLocalPageCache.cpp:52] ["Initialized local page cache from existing PS, stats=<occupied=<total_n=0 total_size=0 max_size=1073741824> evictable=<total_n=0 total_size=0 max_size=1073741824>>"] [thread_id=1]
[2025/12/11 22:26:35.526 +08:00] [WARN] [Context.cpp:1670] ["GlobalStoragePool has already been initialized."] [source=Context] [thread_id=1]
[2025/12/11 22:26:35.526 +08:00] [INFO] [PageStorageImpl.cpp:54] ["PageStorageImpl start. Config{ PageStorageConfig {blob_file_limit_size: 268435456, blob_spacemap_type: 2, blob_heavy_gc_valid_rate: 0.500, blob_heavy_gc_valid_rate_raft_data: 0.050, blob_block_alignment_bytes: 0, wal_roll_size: 2097152, wal_max_persisted_log_files: 4} }"] [source=__global__.log] [thread_id=1]
[2025/12/11 22:26:35.526 +08:00] [INFO] [PageStorageImpl.cpp:54] ["PageStorageImpl start. Config{ PageStorageConfig {blob_file_limit_size: 268435456, blob_spacemap_type: 2, blob_heavy_gc_valid_rate: 0.500, blob_heavy_gc_valid_rate_raft_data: 0.050, blob_block_alignment_bytes: 0, wal_roll_size: 2097152, wal_max_persisted_log_files: 4} }"] [source=__global__.data] [thread_id=1]
[2025/12/11 22:26:35.526 +08:00] [INFO] [PageStorageImpl.cpp:54] ["PageStorageImpl start. Config{ PageStorageConfig {blob_file_limit_size: 268435456, blob_spacemap_type: 2, blob_heavy_gc_valid_rate: 0.500, blob_heavy_gc_valid_rate_raft_data: 0.050, blob_block_alignment_bytes: 0, wal_roll_size: 2097152, wal_max_persisted_log_files: 4} }"] [source=__global__.meta] [thread_id=1]
[2025/12/11 22:26:35.526 +08:00] [INFO] [PageDirectoryFactory.cpp:68] ["PageDirectory restored, max_page_id=0 max_applied_ver=0"] [source=__global__.log] [thread_id=1]
[2025/12/11 22:26:35.527 +08:00] [INFO] [PageDirectoryFactory.cpp:68] ["PageDirectory restored, max_page_id=0 max_applied_ver=0"] [source=__global__.data] [thread_id=1]
[2025/12/11 22:26:35.527 +08:00] [INFO] [PageDirectoryFactory.cpp:68] ["PageDirectory restored, max_page_id=0 max_applied_ver=0"] [source=__global__.meta] [thread_id=1]
[2025/12/11 22:26:35.527 +08:00] [INFO] [DeltaMergeStore.cpp:290] ["Restore DeltaMerge Store start"] [source="keyspace=4294967295 table_id=100"] [thread_id=1]
[2025/12/11 22:26:35.527 +08:00] [DEBUG] [DeltaMergeStore.cpp:2179] ["Loading dt files"] [source="keyspace=4294967295 table_id=100"] [thread_id=1]
[2025/12/11 22:26:35.528 +08:00] [INFO] [StoragePool.cpp:720] ["Finished StoragePool restore. run_mode=ONLY_V3 keyspace=4294967295 table_id=100 max_log_page_id=0 max_data_page_id=0 max_meta_page_id=1"] [source=test.t_100] [thread_id=1]
[2025/12/11 22:26:35.528 +08:00] [INFO] [DeltaMergeStore.cpp:365] ["Restore DeltaMerge Store end, ps_run_mode=ONLY_V3"] [source="keyspace=4294967295 table_id=100"] [thread_id=1]
[2025/12/11 22:26:35.528 +08:00] [INFO] [DeltaMergeStore.cpp:408] ["Release DeltaMerge Store start"] [source="keyspace=4294967295 table_id=100"] [thread_id=1]
[2025/12/11 22:26:35.528 +08:00] [TRACE] [DeltaMergeStore.cpp:523] ["Shutdown DeltaMerge start"] [source="keyspace=4294967295 table_id=100"] [thread_id=1]
[2025/12/11 22:26:35.528 +08:00] [INFO] [LocalIndexerScheduler.cpp:179] ["Removed 0 tasks, keyspace=4294967295 table_id=100"] [thread_id=1]
[2025/12/11 22:26:35.528 +08:00] [TRACE] [DeltaMergeStore.cpp:541] ["Shutdown DeltaMerge end, clear_light_tasks=0 clear_heavy_tasks=0"] [source="keyspace=4294967295 table_id=100"] [thread_id=1]
[2025/12/11 22:26:35.528 +08:00] [INFO] [DeltaMergeStore.cpp:412] ["Release DeltaMerge Store end"] [source="keyspace=4294967295 table_id=100"] [thread_id=1]
[2025/12/11 22:26:35.530 +08:00] [TRACE] [DeltaMergeStore.cpp:636] ["Table write block, rows=4096 bytes=69632"] [source="keyspace=4294967295 table_id=100"] [thread_id=1]
[2025/12/11 22:26:35.530 +08:00] [INFO] [DeltaMergeStore.cpp:2359] ["creating the first segment with segment_id=1"] [source="keyspace=4294967295 table_id=100"] [thread_id=1]
[2025/12/11 22:26:35.530 +08:00] [WARN] [StoragePool.cpp:899] ["The DTFile is already exists, continue to acquire another ID. call=StableValueSpacePtr DB::DM::createNewStable(DMContext &, const ColumnDefinesPtr &, const BlockInputStreamPtr &, PageIdU64, WriteBatches &) path=<mock for existed path> file_id=1"] [source=test.t_100] [thread_id=1]
[2025/12/11 22:26:35.538 +08:00] [DEBUG] [PathPool.cpp:552] ["added new dtfile. [id=2] [path=/tmp-memfs/tiflash-tests/tmp/DMStoreForSegmentReadTaskTest.DisaggReadSnapshot/data/t_100] [real_size=414] [reported_size=0]"] [thread_id=1]
[2025/12/11 22:26:35.539 +08:00] [TRACE] [WriteBatchesImpl.h:120] ["Write into data : E100.2"] [thread_id=1]
[2025/12/11 22:26:35.539 +08:00] [INFO] [WALStore.cpp:143] ["Creating log file for writing, fullname=/tmp-memfs/tiflash-tests/tmp/DMStoreForSegmentReadTaskTest.DisaggReadSnapshot/page/data/wal/log_1_0"] [source=__global__.data] [thread_id=1]
[2025/12/11 22:26:35.539 +08:00] [TRACE] [WriteBatchesImpl.h:239] ["Write into meta : 100.2,100.3,100.1"] [thread_id=1]
[2025/12/11 22:26:35.539 +08:00] [INFO] [BlobStat.cpp:147] ["Created a new BlobStat [blob_id=10] [capacity=268435456]"] [source=__global__.meta] [thread_id=1]
[2025/12/11 22:26:35.540 +08:00] [INFO] [WALStore.cpp:143] ["Creating log file for writing, fullname=/tmp-memfs/tiflash-tests/tmp/DMStoreForSegmentReadTaskTest.DisaggReadSnapshot/page/meta/wal/log_1_0"] [source=__global__.meta] [thread_id=1]
[2025/12/11 22:26:35.541 +08:00] [TRACE] [WriteBatchesImpl.h:120] ["Write into log : 100.1"] [thread_id=1]
[2025/12/11 22:26:35.542 +08:00] [INFO] [BlobStat.cpp:147] ["Created a new BlobStat [blob_id=10] [capacity=268435456]"] [source=__global__.log] [thread_id=1]
[2025/12/11 22:26:35.542 +08:00] [INFO] [WALStore.cpp:143] ["Creating log file for writing, fullname=/tmp-memfs/tiflash-tests/tmp/DMStoreForSegmentReadTaskTest.DisaggReadSnapshot/page/log/wal/log_1_0"] [source=__global__.log] [thread_id=1]
[2025/12/11 22:26:35.542 +08:00] [TRACE] [Segment.cpp:694] ["Segment write to disk, rows=4096 isBigFile=false"] [source="keyspace=4294967295 table_id=100 segment_id=1 epoch=0"] [thread_id=1]
[2025/12/11 22:26:35.543 +08:00] [DEBUG] [DeltaMergeStore.cpp:162] ["Segment task add to background task pool, segment=<segment_id=1 epoch=0 range=[-9223372036854775808,9223372036854775807)> task=Flush by_whom=Write"] [source="keyspace=4294967295 table_id=100"] [thread_id=1]
[2025/12/11 22:26:35.543 +08:00] [DEBUG] [DeltaMergeStore.cpp:180] ["Segment task pop from background task pool, segment=<segment_id=1 epoch=0 range=[-9223372036854775808,9223372036854775807)> task=Flush"] [source="keyspace=4294967295 table_id=100"] [thread_id=6]
[2025/12/11 22:26:35.543 +08:00] [DEBUG] [DeltaValueSpace.cpp:360] ["Flush start, delta=MemTableSet: 1 column files, 4096 rows, 69632 bytes, 0 deletes. ColumnFilePersistedSet [2]: 0 column files, 0 rows, 0 bytes, 0 deletes."] [source="keyspace=4294967295 table_id=100 segment_id=1 epoch=0"] [thread_id=6]
[2025/12/11 22:26:35.543 +08:00] [TRACE] [WriteBatchesImpl.h:239] ["Write into meta : 100.2"] [thread_id=6]
[2025/12/11 22:26:35.543 +08:00] [DEBUG] [ColumnFilePersistedSet.cpp:238] ["ColumnFilePersistedSet [2]: 1 column files, 4096 rows, 69632 bytes, 0 deletes., after append 1 column files, persisted column files: [T_4096]"] [source="keyspace=4294967295 table_id=100 segment_id=1 epoch=0"] [thread_id=6]
[2025/12/11 22:26:35.544 +08:00] [DEBUG] [DeltaValueSpace.cpp:441] ["Flush end, flush_tasks=1 flush_rows=4096 flush_bytes=69632 flush_deletes=0 delta=MemTableSet: 0 column files, 0 rows, 0 bytes, 0 deletes. ColumnFilePersistedSet [2]: 1 column files, 4096 rows, 69632 bytes, 0 deletes."] [source="keyspace=4294967295 table_id=100 segment_id=1 epoch=0"] [thread_id=6]
[2025/12/11 22:26:35.544 +08:00] [DEBUG] [Segment.cpp:2634] ["Begin segment getReadInfo <segment_id=1 epoch=0 range=[-9223372036854775808,9223372036854775807)>"] [source="write seg_id=1"] [thread_id=6]
[2025/12/11 22:26:35.545 +08:00] [DEBUG] [StableValueSpace.cpp:466] ["StableVS getInputStream start_ts=18446744073709551615 enable_handle_clean_read=false is_fast_mode=false enable_del_clean_read=false"] [source="keyspace=4294967295 table_id=100 segment_id=1 epoch=0"] [thread_id=6]
[2025/12/11 22:26:35.545 +08:00] [DEBUG] [DMFilePackFilter.cpp:183] ["RSFilter exclude rate: nan, after_pk: 0, after_read_packs: 0, after_filter: 0, handle_ranges: [[0,9223372036854775807)], read_packs: 0, pack_count: 0, none_count: 0, some_count: 0, all_count: 0, all_null_count: 0"] [source=write] [thread_id=6]
[2025/12/11 22:26:35.556 +08:00] [INFO] [DeltaMergeStore.cpp:920] ["Begin table mergeDeltaAll"] [source="keyspace=4294967295 table_id=100"] [thread_id=1]
[2025/12/11 22:26:35.556 +08:00] [INFO] [DeltaMergeStore_InternalSegment.cpp:1187] ["MergeDelta - Begin, reason=Manual safe_point=0 segment=<segment_id=1 epoch=0 range=[-9223372036854775808,9223372036854775807) next_segment_id=0 delta_rows=4096 delta_bytes=69632 delta_deletes=0 stable_file=[dmf_2(v=0)] stable_rows=0 stable_bytes=0 dmf_rows=0 dmf_bytes=0 dmf_packs=0>"] [source="keyspace=4294967295 table_id=100"] [thread_id=1]
[2025/12/11 22:26:35.556 +08:00] [DEBUG] [DeltaValueSpace.h:241] ["Cannot get update lock because DeltaValueSpace is updating. Current update operation will be discarded, delta=<delta_id=2>"] [source="keyspace=4294967295 table_id=100 segment_id=1 epoch=0"] [thread_id=1]
[2025/12/11 22:26:35.556 +08:00] [DEBUG] [DeltaMergeStore_InternalSegment.cpp:1213] ["MergeDelta - Give up segmentMergeDelta because snapshot failed, segment=<segment_id=1 epoch=0 range=[-9223372036854775808,9223372036854775807)>"] [source="keyspace=4294967295 table_id=100"] [thread_id=1]
[2025/12/11 22:26:35.556 +08:00] [INFO] [DeltaMergeStore.cpp:941] ["Finish table mergeDeltaAll: false"] [source="keyspace=4294967295 table_id=100"] [thread_id=1]
[2025/12/11 22:26:35.556 +08:00] [INFO] [DeltaMergeStore.cpp:817] ["Table delete range, range=[0,128)"] [source="keyspace=4294967295 table_id=100"] [thread_id=1]
[2025/12/11 22:26:35.556 +08:00] [TRACE] [Segment.cpp:741] ["Segment write delete range, delete_range=[0,128)"] [source="keyspace=4294967295 table_id=100 segment_id=1 epoch=0"] [thread_id=1]
[2025/12/11 22:26:35.573 +08:00] [DEBUG] [PathPool.cpp:552] ["added new dtfile. [id=3] [path=/tmp-memfs/tiflash-tests/tmp/DMStoreForSegmentReadTaskTest.DisaggReadSnapshot/data/t_100] [real_size=1511] [reported_size=621]"] [thread_id=1]
[2025/12/11 22:26:35.578 +08:00] [INFO] [DeltaMergeStore_Ingest.cpp:740] ["Table ingest files - begin, use_split_replace=false files=[<file=dmf_3 range=[0,128)>] rows=128 bytes=2176 bytes_on_disk=621 range=[0,128) clear=false"] [source="keyspace=4294967295 table_id=100"] [thread_id=1]
[2025/12/11 22:26:35.578 +08:00] [TRACE] [WriteBatchesImpl.h:120] ["Write into data : E100.3"] [thread_id=1]
[2025/12/11 22:26:35.581 +08:00] [DEBUG] [Segment.cpp:2897] ["Finish segment ensurePlace, read_ranges=[[-9223372036854775808,9223372036854775807)] placed_items=1 shared_delta_index=<placed_rows=0 placed_deletes=0 tree_entries=0 tree_inserts=0 tree_deletes=0> my_delta_index=<placed_rows=4096 placed_deletes=0 tree_entries=4096 tree_inserts=4096 tree_deletes=0> <segment_id=1 epoch=0 range=[-9223372036854775808,9223372036854775807)>"] [source="write seg_id=1"] [thread_id=6]
[2025/12/11 22:26:35.583 +08:00] [TRACE] [WriteBatchesImpl.h:120] ["Write into data : 100.4 > 100.3"] [thread_id=1]
[2025/12/11 22:26:35.583 +08:00] [TRACE] [Segment.cpp:824] ["Segment ingest data to delta, range=[0,128) clear=false"] [source="keyspace=4294967295 table_id=100 segment_id=1 epoch=0"] [thread_id=1]
[2025/12/11 22:26:35.583 +08:00] [DEBUG] [Segment.cpp:2661] ["Finish segment getReadInfo, my_delta_index=<placed_rows=4096 placed_deletes=0 tree_entries=4096 tree_inserts=4096 tree_deletes=0> fully_indexed=true read_ranges=[[-9223372036854775808,9223372036854775807)] snap={stable_rows=0 persisted_rows=4096 persisted_dels=0 persisted_cfs=1 mem_rows=0 mem_dels=0 mem_cfs=0} <segment_id=1 epoch=0 range=[-9223372036854775808,9223372036854775807)>"] [source="write seg_id=1"] [thread_id=6]
[2025/12/11 22:26:35.583 +08:00] [DEBUG] [Segment.cpp:2673] ["Segment updated delta index, my_delta_index=<placed_rows=4096 placed_deletes=0 tree_entries=4096 tree_inserts=4096 tree_deletes=0> <segment_id=1 epoch=0 range=[-9223372036854775808,9223372036854775807)>"] [source="write seg_id=1"] [thread_id=6]
[2025/12/11 22:26:35.584 +08:00] [DEBUG] [DMFilePackFilter.cpp:183] ["RSFilter exclude rate: 0.00, after_pk: 1, after_read_packs: 1, after_filter: 1, handle_ranges: [[-9223372036854775808,9223372036854775807)], read_packs: 0, pack_count: 1, none_count: 0, some_count: 1, all_count: 0, all_null_count: 0"] [thread_id=1]
[2025/12/11 22:26:35.584 +08:00] [TRACE] [WriteBatchesImpl.h:191] ["Rollback remove from data_wb : X100.3"] [thread_id=1]
[2025/12/11 22:26:35.584 +08:00] [INFO] [DeltaMergeStore_Ingest.cpp:842] ["Table ingest files - finished ingested files into segments, ingested_files=[<file=dmf_3 range=[0,128)>] updated_segments=[<segment_id=1 epoch=0 range=[-9223372036854775808,9223372036854775807)>] clear=false"] [source="keyspace=4294967295 table_id=100"] [thread_id=1]
[2025/12/11 22:26:35.584 +08:00] [DEBUG] [DeltaValueSpace.cpp:360] ["Flush start, delta=MemTableSet: 2 column files, 128 rows, 2176 bytes, 1 deletes. ColumnFilePersistedSet [2]: 1 column files, 4096 rows, 69632 bytes, 0 deletes."] [source="keyspace=4294967295 table_id=100 segment_id=1 epoch=0"] [thread_id=1]
[2025/12/11 22:26:35.585 +08:00] [TRACE] [WriteBatchesImpl.h:239] ["Write into meta : 100.2"] [thread_id=1]
[2025/12/11 22:26:35.585 +08:00] [DEBUG] [ColumnFilePersistedSet.cpp:238] ["ColumnFilePersistedSet [2]: 3 column files, 4224 rows, 71808 bytes, 1 deletes., after append 2 column files, persisted column files: [T_4096,D_[0,128),F_128]"] [source="keyspace=4294967295 table_id=100 segment_id=1 epoch=0"] [thread_id=1]
[2025/12/11 22:26:35.585 +08:00] [DEBUG] [DeltaValueSpace.cpp:441] ["Flush end, flush_tasks=2 flush_rows=128 flush_bytes=2176 flush_deletes=1 delta=MemTableSet: 0 column files, 0 rows, 0 bytes, 0 deletes. ColumnFilePersistedSet [2]: 3 column files, 4224 rows, 71808 bytes, 1 deletes."] [source="keyspace=4294967295 table_id=100 segment_id=1 epoch=0"] [thread_id=1]
[2025/12/11 22:26:35.586 +08:00] [TRACE] [DeltaMergeStore.cpp:636] ["Table write block, rows=128 bytes=2176"] [source="keyspace=4294967295 table_id=100"] [thread_id=1]
[2025/12/11 22:26:35.586 +08:00] [TRACE] [Segment.cpp:700] ["Segment write to cache, rows=128"] [source="keyspace=4294967295 table_id=100 segment_id=1 epoch=0"] [thread_id=1]
[2025/12/11 22:26:35.586 +08:00] [DEBUG] [DeltaValueSpace.cpp:360] ["Flush start, delta=MemTableSet: 1 column files, 128 rows, 2176 bytes, 0 deletes. ColumnFilePersistedSet [2]: 3 column files, 4224 rows, 71808 bytes, 1 deletes."] [source="keyspace=4294967295 table_id=100 segment_id=1 epoch=0"] [thread_id=1]
[2025/12/11 22:26:35.587 +08:00] [TRACE] [WriteBatchesImpl.h:120] ["Write into log : 100.2"] [thread_id=1]
[2025/12/11 22:26:35.588 +08:00] [TRACE] [WriteBatchesImpl.h:239] ["Write into meta : 100.2"] [thread_id=1]
[2025/12/11 22:26:35.588 +08:00] [DEBUG] [ColumnFilePersistedSet.cpp:238] ["ColumnFilePersistedSet [2]: 4 column files, 4352 rows, 73984 bytes, 1 deletes., after append 1 column files, persisted column files: [T_4096,D_[0,128),F_128,T_128]"] [source="keyspace=4294967295 table_id=100 segment_id=1 epoch=0"] [thread_id=1]
[2025/12/11 22:26:35.588 +08:00] [DEBUG] [DeltaValueSpace.cpp:441] ["Flush end, flush_tasks=1 flush_rows=128 flush_bytes=2176 flush_deletes=0 delta=MemTableSet: 0 column files, 0 rows, 0 bytes, 0 deletes. ColumnFilePersistedSet [2]: 4 column files, 4352 rows, 73984 bytes, 1 deletes."] [source="keyspace=4294967295 table_id=100 segment_id=1 epoch=0"] [thread_id=1]
[2025/12/11 22:26:35.589 +08:00] [TRACE] [DeltaMergeStore.cpp:636] ["Table write block, rows=128 bytes=2176"] [source="keyspace=4294967295 table_id=100"] [thread_id=1]
[2025/12/11 22:26:35.589 +08:00] [TRACE] [Segment.cpp:700] ["Segment write to cache, rows=128"] [source="keyspace=4294967295 table_id=100 segment_id=1 epoch=0"] [thread_id=1]
[2025/12/11 22:26:35.589 +08:00] [DEBUG] [DeltaValueSpace.cpp:360] ["Flush start, delta=MemTableSet: 1 column files, 128 rows, 2176 bytes, 0 deletes. ColumnFilePersistedSet [2]: 4 column files, 4352 rows, 73984 bytes, 1 deletes."] [source="keyspace=4294967295 table_id=100 segment_id=1 epoch=0"] [thread_id=1]
[2025/12/11 22:26:35.590 +08:00] [TRACE] [WriteBatchesImpl.h:120] ["Write into log : 100.3"] [thread_id=1]
[2025/12/11 22:26:35.590 +08:00] [TRACE] [WriteBatchesImpl.h:239] ["Write into meta : 100.2"] [thread_id=1]
[2025/12/11 22:26:35.591 +08:00] [DEBUG] [ColumnFilePersistedSet.cpp:238] ["ColumnFilePersistedSet [2]: 5 column files, 4480 rows, 76160 bytes, 1 deletes., after append 1 column files, persisted column files: [T_4096,D_[0,128),F_128,T_128,T_128]"] [source="keyspace=4294967295 table_id=100 segment_id=1 epoch=0"] [thread_id=1]
[2025/12/11 22:26:35.591 +08:00] [DEBUG] [DeltaValueSpace.cpp:441] ["Flush end, flush_tasks=1 flush_rows=128 flush_bytes=2176 flush_deletes=0 delta=MemTableSet: 0 column files, 0 rows, 0 bytes, 0 deletes. ColumnFilePersistedSet [2]: 5 column files, 4480 rows, 76160 bytes, 1 deletes."] [source="keyspace=4294967295 table_id=100 segment_id=1 epoch=0"] [thread_id=1]
[2025/12/11 22:26:35.591 +08:00] [TRACE] [DeltaMergeStore.cpp:636] ["Table write block, rows=128 bytes=2176"] [source="keyspace=4294967295 table_id=100"] [thread_id=1]
[2025/12/11 22:26:35.591 +08:00] [TRACE] [Segment.cpp:700] ["Segment write to cache, rows=128"] [source="keyspace=4294967295 table_id=100 segment_id=1 epoch=0"] [thread_id=1]
[2025/12/11 22:26:35.592 +08:00] [INFO] [DeltaMergeStore.cpp:2288] ["Segment read tasks build done, cost=0ms sorted_ranges=1 n_tasks_before_split=1 n_tasks_final=1 n_ranges_final=1 segments=[s0_t100_1_0_24985326994047330_4608]"] [source="keyspace=4294967295 table_id=100 req_id"] [thread_id=1]
[2025/12/11 22:26:35.592 +08:00] [INFO] [DeltaMergeStore.cpp:1559] ["Read create segment snapshot done"] [source="keyspace=4294967295 table_id=100 req_id"] [thread_id=1]
[2025/12/11 22:26:35.599 +08:00] [DEBUG] [Serializer.cpp:286] ["Rebuild local ColumnFileInMemory from remote, rows=128"] [thread_id=1]
[2025/12/11 22:26:35.599 +08:00] [DEBUG] [Serializer.cpp:396] ["Rebuild local ColumnFileDeleteRange from remote, range=[0,128)"] [thread_id=1]
[2025/12/11 22:26:35.599 +08:00] [DEBUG] [Serializer.cpp:420] ["Rebuild local ColumnFileBig from remote, key=/tmp-memfs/tiflash-tests/tmp/DMStoreForSegmentReadTaskTest.DisaggReadSnapshot/data/t_100/stable/dmf_3"] [thread_id=1]
[2025/12/11 22:26:35.605 +08:00] [DEBUG] [SegmentReadTask.cpp:179] ["memory_cfs_count=1 memory_page_count=0 persisted_cfs_count=5 persisted_page_count=3 remote_page_ids=[1, 2, 3] delta_index=<placed_rows=0 placed_deletes=0 tree_entries=0 tree_inserts=0 tree_deletes=0> store_address=127.0.0.1"] [source=" segment_id=1 epoch=0 delta_epoch=24985326994047330"] [thread_id=1]
/home/jenkins/agent/workspace/tiflash-build-common/tiflash/dbms/src/Storages/DeltaMerge/tests/gtest_segment_read_task.cpp:773: Failure
Expected equality of these values:
persist_set_wn->getColumnFileCount()
Which is: 5
4
[2025/12/11 22:26:35.606 +08:00] [ERROR] [Exception.cpp:93] ["std::exception. Code: 1001, type: testing::AssertionException, e.what() = /home/jenkins/agent/workspace/tiflash-build-common/tiflash/dbms/src/Storages/DeltaMerge/tests/gtest_segment_read_task.cpp:773: Failure\nExpected equality of these values:\n persist_set_wn->getColumnFileCount()\n Which is: 5\n 4"] [source="virtual void DB::DM::tests::DMStoreForSegmentReadTaskTest_DisaggReadSnapshot_Test::TestBody()"] [thread_id=1]
/home/jenkins/agent/workspace/tiflash-build-common/tiflash/dbms/src/Storages/DeltaMerge/tests/gtest_segment_read_task.cpp:822: Failure
Failed
[2025/12/11 22:26:35.607 +08:00] [INFO] [DeltaMergeStore.cpp:408] ["Release DeltaMerge Store start"] [source="keyspace=4294967295 table_id=100"] [thread_id=1]
[2025/12/11 22:26:35.607 +08:00] [TRACE] [DeltaMergeStore.cpp:523] ["Shutdown DeltaMerge start"] [source="keyspace=4294967295 table_id=100"] [thread_id=1]
[2025/12/11 22:26:35.607 +08:00] [INFO] [LocalIndexerScheduler.cpp:179] ["Removed 0 tasks, keyspace=4294967295 table_id=100"] [thread_id=1]
[2025/12/11 22:26:35.607 +08:00] [TRACE] [DeltaMergeStore.cpp:541] ["Shutdown DeltaMerge end, clear_light_tasks=0 clear_heavy_tasks=0"] [source="keyspace=4294967295 table_id=100"] [thread_id=1]
[2025/12/11 22:26:35.607 +08:00] [INFO] [DeltaMergeStore.cpp:412] ["Release DeltaMerge Store end"] [source="keyspace=4294967295 table_id=100"] [thread_id=1]
�[0;31m[ FAILED ] �[mDMStoreForSegmentReadTaskTest.DisaggReadSnapshot (91 ms)
�[0;32m[----------] �[m1 test from DMStoreForSegmentReadTaskTest (91 ms total)
�[0;32m[----------] �[mGlobal test environment tear-down
�[0;32m[==========] �[m1 test from 1 test case ran. (91 ms total)
�[0;32m[ PASSED ] �[m0 tests.
�[0;31m[ FAILED ] �[m1 test, listed below:
�[0;31m[ FAILED ] �[mDMStoreForSegmentReadTaskTest.DisaggReadSnapshot
3. What did you see instead (Required)
4. What is your TiFlash version? (Required)
#10607
https://do.pingcap.net/jenkins/blue/organizations/jenkins/pingcap%2Ftiflash%2Fpull_unit_test/detail/pull_unit_test/5241/pipeline/