Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

unstable test RegionKVStoreV2Test.KVStoreSingleSnap4 #8625

Closed
JaySon-Huang opened this issue Dec 29, 2023 · 3 comments · Fixed by #8614
Closed

unstable test RegionKVStoreV2Test.KVStoreSingleSnap4 #8625

JaySon-Huang opened this issue Dec 29, 2023 · 3 comments · Fixed by #8614
Assignees
@CalvinNeo
Labels
component/storage severity/moderate type/bug The issue is confirmed as a bug.

Comments

@JaySon-Huang
Copy link
Contributor

JaySon-Huang commented Dec 29, 2023 •
edited
Loading

Bug Report

Please answer these questions before submitting your issue. Thanks!

1. Minimal reproduce step (Required)

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

3. What did you see instead (Required)

https://ci.pingcap.net/blue/organizations/jenkins/tiflash-ghpr-unit-tests/detail/tiflash-ghpr-unit-tests/12407/pipeline/

[1238/2415] RegionKVStoreV2Test.KVStoreSingleSnap4 (1849 ms)
... ......
�[0;33mNote: Google Test filter = RegionKVStoreV2Test.KVStoreSingleSnap4
�[m�[0;32m[==========] �[mRunning 1 test from 1 test case.
�[0;32m[----------] �[mGlobal test environment set-up.
�[0;32m[----------] �[m1 test from RegionKVStoreV2Test
�[0;32m[ RUN      ] �[mRegionKVStoreV2Test.KVStoreSingleSnap4
[2023/12/29 09:33:16.443 +08:00] [INFO] [TiFlashTestEnv.cpp:258] ["Clean path /tmp-memfs/tiflash-tests/tmp/region_kvs_v2_test for bootstrap"] [source=Test] [thread_id=1]
[2023/12/29 09:33:16.443 +08:00] [WARN] [ProxyFFI.cpp:895] ["Set mock rust ptr gc function"] [source=MockSetRustGcHelper] [thread_id=1]
[2023/12/29 09:33:16.444 +08:00] [INFO] [KVStore.cpp:70] ["KVStore inited, eager_raft_log_gc_enabled=false"] [thread_id=1]
[2023/12/29 09:33:16.444 +08:00] [INFO] [PageStorageImpl.cpp:56] ["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=RegionPersister] [thread_id=1]
[2023/12/29 09:33:16.444 +08:00] [INFO] [PageDirectoryFactory.cpp:68] ["PageDirectory restored, max_page_id=0 max_applied_ver=0"] [source=RegionPersister] [thread_id=1]
[2023/12/29 09:33:16.444 +08:00] [INFO] [RegionPersister.cpp:381] ["RegionPersister running. Current Run Mode is ONLY_V3"] [thread_id=1]
[2023/12/29 09:33:16.444 +08:00] [INFO] [KVStore.cpp:84] ["Restored 0 regions"] [thread_id=1]
[2023/12/29 09:33:16.445 +08:00] [INFO] [KVStore.cpp:131] ["Parsed proxy config snap_handle_pool_size 4"] [thread_id=1]
[2023/12/29 09:33:16.449 +08:00] [INFO] [KVStore.cpp:616] ["Set store info id: 1234"] [thread_id=1]
[2023/12/29 09:33:16.449 +08:00] [INFO] [kvstore_helper.h:100] ["Finished setup"] [source=RegionKVStoreV2Test] [thread_id=1]
[2023/12/29 09:33:16.449 +08:00] [WARN] [Context.cpp:1732] ["GlobalStoragePool has already been initialized."] [source=Context] [thread_id=1]
[2023/12/29 09:33:16.449 +08:00] [INFO] [PageStorageImpl.cpp:56] ["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]
[2023/12/29 09:33:16.449 +08:00] [INFO] [PageStorageImpl.cpp:56] ["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]
[2023/12/29 09:33:16.449 +08:00] [INFO] [PageStorageImpl.cpp:56] ["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]
[2023/12/29 09:33:16.450 +08:00] [INFO] [PageDirectoryFactory.cpp:68] ["PageDirectory restored, max_page_id=0 max_applied_ver=0"] [source=__global__.log] [thread_id=1]
[2023/12/29 09:33:16.450 +08:00] [INFO] [PageDirectoryFactory.cpp:68] ["PageDirectory restored, max_page_id=0 max_applied_ver=0"] [source=__global__.data] [thread_id=1]
[2023/12/29 09:33:16.450 +08:00] [INFO] [PageDirectoryFactory.cpp:68] ["PageDirectory restored, max_page_id=0 max_applied_ver=0"] [source=__global__.meta] [thread_id=1]
[2023/12/29 09:33:16.450 +08:00] [INFO] [TiDBSchemaSyncer.cpp:74] ["Start to sync schemas. current version is: 0 and try to sync schema version to: 4"] [source="keyspace=4294967295"] [thread_id=1]
[2023/12/29 09:33:16.450 +08:00] [INFO] [SchemaBuilder.cpp:1258] ["Sync all schemas begin"] [source="keyspace=4294967295"] [thread_id=1]
[2023/12/29 09:33:16.451 +08:00] [INFO] [SchemaBuilder.cpp:889] ["Create database default begin, database_id=0"] [source="keyspace=4294967295"] [thread_id=98]
[2023/12/29 09:33:16.451 +08:00] [INFO] [SchemaBuilder.cpp:889] ["Create database d begin, database_id=1"] [source="keyspace=4294967295"] [thread_id=99]
[2023/12/29 09:33:16.481 +08:00] [INFO] [DatabaseTiFlash.cpp:130] ["Total 0 tables in database db_0"] [source="DatabaseTiFlash (db_0)"] [thread_id=98]
[2023/12/29 09:33:16.481 +08:00] [INFO] [SchemaBuilder.cpp:902] ["Create database default end, database_id=0"] [source="keyspace=4294967295"] [thread_id=98]
[2023/12/29 09:33:16.481 +08:00] [INFO] [SchemaBuilder.cpp:1290] ["Database default created during sync all schemas, database_id=0"] [source="keyspace=4294967295"] [thread_id=98]
[2023/12/29 09:33:16.485 +08:00] [INFO] [DatabaseTiFlash.cpp:130] ["Total 0 tables in database db_1"] [source="DatabaseTiFlash (db_1)"] [thread_id=99]
[2023/12/29 09:33:16.485 +08:00] [INFO] [SchemaBuilder.cpp:902] ["Create database d end, database_id=1"] [source="keyspace=4294967295"] [thread_id=99]
[2023/12/29 09:33:16.486 +08:00] [INFO] [SchemaBuilder.cpp:1290] ["Database d created during sync all schemas, database_id=1"] [source="keyspace=4294967295"] [thread_id=99]
[2023/12/29 09:33:16.486 +08:00] [INFO] [SchemaBuilder.cpp:1301] ["Table d.prevt1804289383 syncing during sync all schemas, database_id=1 table_id=30"] [source="keyspace=4294967295"] [thread_id=99]
[2023/12/29 09:33:16.486 +08:00] [DEBUG] [SchemaBuilder.cpp:1320] ["register table to table_id_map, database_id=1 table_id=30"] [source="keyspace=4294967295"] [thread_id=99]
[2023/12/29 09:33:16.486 +08:00] [INFO] [SchemaBuilder.cpp:1088] ["Create table db_1.prevt1804289383 begin, database_id=1, table_id=30"] [source="keyspace=4294967295"] [thread_id=99]
[2023/12/29 09:33:16.486 +08:00] [INFO] [SchemaBuilder.cpp:780] ["Storage instance does not exist, tryRecoverPhysicalTable is ignored, table_id=30"] [source="keyspace=4294967295"] [thread_id=99]
[2023/12/29 09:33:16.488 +08:00] [DEBUG] [SchemaBuilder.cpp:1030] ["Analyzing table info : {\"cols\":[{\"comment\":\"\",\"default\":null,\"default_bit\":null,\"id\":1,\"name\":{\"L\":\"a\",\"O\":\"a\"},\"offset\":-1,\"origin_default\":null,\"state\":0,\"type\":{\"Charset\":null,\"Collate\":null,\"Decimal\":0,\"Elems\":null,\"Flag\":4097,\"Flen\":0,\"Tp\":8}}],\"comment\":\"Mocked.\",\"id\":30,\"index_info\":[],\"is_common_handle\":false,\"keyspace_id\":4294967295,\"name\":{\"L\":\"prevt1804289383\",\"O\":\"prevt1804289383\"},\"partition\":null,\"pk_is_handle\":false,\"schema_version\":-1,\"state\":0,\"tiflash_replica\":{\"Count\":0},\"update_timestamp\":1703813596450655}"] [source="keyspace=4294967295"] [thread_id=99]
[2023/12/29 09:33:16.491 +08:00] [INFO] [SchemaBuilder.cpp:1122] ["Create table db_1.prevt1804289383 (database_id=1 table_id=30) with statement: CREATE TABLE `db_1`.`t_30`(`a` Int64, `_tidb_rowid` Int64) Engine = DeltaMerge((`_tidb_rowid`), '{\"cols\":[{\"comment\":\"\",\"default\":null,\"default_bit\":null,\"id\":1,\"name\":{\"L\":\"a\",\"O\":\"a\"},\"offset\":-1,\"origin_default\":null,\"state\":0,\"type\":{\"Charset\":null,\"Collate\":null,\"Decimal\":0,\"Elems\":null,\"Flag\":4097,\"Flen\":0,\"Tp\":8}}],\"comment\":\"Mocked.\",\"id\":30,\"index_info\":[],\"is_common_handle\":false,\"keyspace_id\":4294967295,\"name\":{\"L\":\"prevt1804289383\",\"O\":\"prevt1804289383\"},\"partition\":null,\"pk_is_handle\":false,\"schema_version\":-1,\"state\":0,\"tiflash_replica\":{\"Count\":0},\"update_timestamp\":1703813596450655}', 0)"] [source="keyspace=4294967295"] [thread_id=99]
[2023/12/29 09:33:16.496 +08:00] [INFO] [StorageDeltaMerge.cpp:126] ["updateTableColumnInfo, table_name=t_30 ordinary=\"columns format version: 1\n2 columns:\n`a` Int64\n`_tidb_rowid` Int64\n\" materialized=\"columns format version: 1\n0 columns:\n\""] [source=db_1.t_30] [thread_id=99]
[2023/12/29 09:33:16.497 +08:00] [INFO] [SchemaBuilder.cpp:1166] ["Creat table db_1.prevt1804289383 end, database_id=1 table_id=30"] [source="keyspace=4294967295"] [thread_id=99]
[2023/12/29 09:33:16.497 +08:00] [INFO] [SchemaBuilder.cpp:1301] ["Table d.t846930886 syncing during sync all schemas, database_id=1 table_id=31"] [source="keyspace=4294967295"] [thread_id=99]
[2023/12/29 09:33:16.497 +08:00] [DEBUG] [SchemaBuilder.cpp:1320] ["register table to table_id_map, database_id=1 table_id=31"] [source="keyspace=4294967295"] [thread_id=99]
[2023/12/29 09:33:16.497 +08:00] [INFO] [SchemaBuilder.cpp:1088] ["Create table db_1.t846930886 begin, database_id=1, table_id=31"] [source="keyspace=4294967295"] [thread_id=99]
[2023/12/29 09:33:16.498 +08:00] [INFO] [SchemaBuilder.cpp:780] ["Storage instance does not exist, tryRecoverPhysicalTable is ignored, table_id=31"] [source="keyspace=4294967295"] [thread_id=99]
[2023/12/29 09:33:16.499 +08:00] [DEBUG] [SchemaBuilder.cpp:1030] ["Analyzing table info : {\"cols\":[{\"comment\":\"\",\"default\":null,\"default_bit\":null,\"id\":1,\"name\":{\"L\":\"a\",\"O\":\"a\"},\"offset\":-1,\"origin_default\":null,\"state\":0,\"type\":{\"Charset\":null,\"Collate\":null,\"Decimal\":0,\"Elems\":null,\"Flag\":4097,\"Flen\":0,\"Tp\":8}}],\"comment\":\"Mocked.\",\"id\":31,\"index_info\":[],\"is_common_handle\":false,\"keyspace_id\":4294967295,\"name\":{\"L\":\"t846930886\",\"O\":\"t846930886\"},\"partition\":null,\"pk_is_handle\":false,\"schema_version\":-1,\"state\":0,\"tiflash_replica\":{\"Count\":0},\"update_timestamp\":1703813596450655}"] [source="keyspace=4294967295"] [thread_id=99]
[2023/12/29 09:33:16.501 +08:00] [INFO] [SchemaBuilder.cpp:1122] ["Create table db_1.t846930886 (database_id=1 table_id=31) with statement: CREATE TABLE `db_1`.`t_31`(`a` Int64, `_tidb_rowid` Int64) Engine = DeltaMerge((`_tidb_rowid`), '{\"cols\":[{\"comment\":\"\",\"default\":null,\"default_bit\":null,\"id\":1,\"name\":{\"L\":\"a\",\"O\":\"a\"},\"offset\":-1,\"origin_default\":null,\"state\":0,\"type\":{\"Charset\":null,\"Collate\":null,\"Decimal\":0,\"Elems\":null,\"Flag\":4097,\"Flen\":0,\"Tp\":8}}],\"comment\":\"Mocked.\",\"id\":31,\"index_info\":[],\"is_common_handle\":false,\"keyspace_id\":4294967295,\"name\":{\"L\":\"t846930886\",\"O\":\"t846930886\"},\"partition\":null,\"pk_is_handle\":false,\"schema_version\":-1,\"state\":0,\"tiflash_replica\":{\"Count\":0},\"update_timestamp\":1703813596450655}', 0)"] [source="keyspace=4294967295"] [thread_id=99]
[2023/12/29 09:33:16.504 +08:00] [INFO] [StorageDeltaMerge.cpp:126] ["updateTableColumnInfo, table_name=t_31 ordinary=\"columns format version: 1\n2 columns:\n`a` Int64\n`_tidb_rowid` Int64\n\" materialized=\"columns format version: 1\n0 columns:\n\""] [source=db_1.t_31] [thread_id=99]
[2023/12/29 09:33:16.505 +08:00] [INFO] [SchemaBuilder.cpp:1166] ["Creat table db_1.t846930886 end, database_id=1 table_id=31"] [source="keyspace=4294967295"] [thread_id=99]
[2023/12/29 09:33:16.505 +08:00] [INFO] [SchemaBuilder.cpp:1383] ["Sync all schemas end"] [source="keyspace=4294967295"] [thread_id=1]
[2023/12/29 09:33:16.505 +08:00] [INFO] [TiDBSchemaSyncer.cpp:108] ["End sync schema, version has been updated to 4"] [source="keyspace=4294967295"] [thread_id=1]
[2023/12/29 09:33:16.506 +08:00] [INFO] [RegionTable.cpp:49] ["get new table, keyspace=4294967295 table_id=31"] [thread_id=1]
[2023/12/29 09:33:16.516 +08:00] [DEBUG] [PartitionStreams.cpp:451] ["Get schema, keyspace=4294967295 table_id=31"] [source="std::tuple<TableLockHolder, std::shared_ptr<StorageDeltaMerge>, DecodingStorageSchemaSnapshotConstPtr> DB::AtomicGetStorageSchema(const DB::RegionPtr &, DB::TMTContext &)"] [thread_id=1]
[2023/12/29 09:33:16.516 +08:00] [INFO] [DeltaMergeStore.cpp:238] ["Restore DeltaMerge Store start"] [source="keyspace=4294967295 table_id=31"] [thread_id=1]
[2023/12/29 09:33:16.516 +08:00] [DEBUG] [DeltaMergeStore.cpp:1966] ["Loading dt files"] [source="keyspace=4294967295 table_id=31"] [thread_id=1]
[2023/12/29 09:33:16.517 +08:00] [TRACE] [StoragePool.cpp:806] ["Finished StoragePool restore. [current_run_mode=ONLY_V3] [ns_id=31] [max_log_page_id=0] [max_data_page_id=0] [max_meta_page_id=0]"] [source=db_1.t_31] [thread_id=1]
[2023/12/29 09:33:16.517 +08:00] [INFO] [DeltaMergeStore.cpp:308] ["Restore DeltaMerge Store end, ps_run_mode=ONLY_V3"] [source="keyspace=4294967295 table_id=31"] [thread_id=1]
[2023/12/29 09:33:16.518 +08:00] [INFO] [SSTReader.h:190] ["Open sst file first !2_multi_0 range [7480000000000000FF1F5F728000000000FF0000000000000000FA,7480000000000000FF1F5F728000000000FF00005A0000000000FA] split_id=18446744073709551615"] [source="keyspace=4294967295 table_id=31"] [thread_id=1]
[2023/12/29 09:33:16.518 +08:00] [INFO] [SSTReader.cpp:132] ["Seek cf Default to 7480000000000000FF1F5F728000000000FF0000000000000000FA, split_id=18446744073709551615"] [source=MonoSSTReader] [thread_id=1]
[2023/12/29 09:33:16.518 +08:00] [INFO] [SSTReader.h:190] ["Open sst file first !2_multi_0 range [7480000000000000FF1F5F728000000000FF0000000000000000FA,7480000000000000FF1F5F728000000000FF00005A0000000000FA] split_id=18446744073709551615"] [source="keyspace=4294967295 table_id=31"] [thread_id=1]
[2023/12/29 09:33:16.518 +08:00] [INFO] [SSTReader.cpp:132] ["Seek cf Write to 7480000000000000FF1F5F728000000000FF0000000000000000FA, split_id=18446744073709551615"] [source=MonoSSTReader] [thread_id=1]
[2023/12/29 09:33:16.518 +08:00] [INFO] [SSTFilesToBlockInputStream.cpp:129] ["Finish Construct MultiSSTReader, write=1 lock=0 default=1 region_id=2 snapshot_index=6"] [source="keyspace=4294967295 table_id=31"] [thread_id=1]
[2023/12/29 09:33:16.519 +08:00] [INFO] [PrehandleSnapshot.cpp:388] ["getSplitKey result 7480000000000000FF1F5F728000000000FF0000190000000000FAFFFFFFFFFFFFFF90:7480000000000000FF1F5F728000000000FF0000310000000000FAFFFFFFFFFFFFFF90:7480000000000000FF1F5F728000000000FF0000490000000000FAFFFFFFFFFFFFFF90, total_concurrency=4 ongoing=1 total_split_parts=4 split_keys=3 region_range=[7480000000000000FF1F5F728000000000FF0000000000000000FA,7480000000000000FF1F5F728000000000FF00005A0000000000FA] approx_bytes=1980 region_id=2"] [thread_id=1]
[2023/12/29 09:33:16.519 +08:00] [DEBUG] [PrehandleSnapshot.cpp:78] ["Prehandle resource meet, limit=4, current=4, region_id=2"] [source=PreHandlingTrace] [thread_id=1]
[2023/12/29 09:33:16.519 +08:00] [INFO] [PrehandleSnapshot.cpp:511] ["Parallel prehandling for single big region, range=[7480000000000000FF1F5F728000000000FF0000000000000000FA,7480000000000000FF1F5F728000000000FF00005A0000000000FA], split keys=3, region_id=2"] [thread_id=1]
[2023/12/29 09:33:16.519 +08:00] [INFO] [SSTReader.h:190] ["Open sst file first !2_multi_0 range [7480000000000000FF1F5F728000000000FF0000000000000000FA,7480000000000000FF1F5F728000000000FF00005A0000000000FA] split_id=0"] [source="keyspace=4294967295 table_id=31"] [thread_id=98]
[2023/12/29 09:33:16.520 +08:00] [INFO] [SSTReader.cpp:132] ["Seek cf Default to 7480000000000000FF1F5F728000000000FF0000000000000000FA, split_id=0"] [source=MonoSSTReader] [thread_id=98]
[2023/12/29 09:33:16.520 +08:00] [INFO] [SSTReader.h:190] ["Open sst file first !2_multi_0 range [7480000000000000FF1F5F728000000000FF0000000000000000FA,7480000000000000FF1F5F728000000000FF00005A0000000000FA] split_id=0"] [source="keyspace=4294967295 table_id=31"] [thread_id=98]
[2023/12/29 09:33:16.520 +08:00] [INFO] [SSTReader.cpp:132] ["Seek cf Write to 7480000000000000FF1F5F728000000000FF0000000000000000FA, split_id=0"] [source=MonoSSTReader] [thread_id=98]
[2023/12/29 09:33:16.520 +08:00] [INFO] [SSTReader.h:190] ["Open sst file first !2_multi_0 range [7480000000000000FF1F5F728000000000FF0000000000000000FA,7480000000000000FF1F5F728000000000FF00005A0000000000FA] split_id=1"] [source="keyspace=4294967295 table_id=31"] [thread_id=99]
[2023/12/29 09:33:16.520 +08:00] [INFO] [SSTFilesToBlockInputStream.cpp:129] ["Finish Construct MultiSSTReader, write=1 lock=0 default=1 region_id=2 snapshot_index=6"] [source="keyspace=4294967295 table_id=31"] [thread_id=98]
[2023/12/29 09:33:16.520 +08:00] [INFO] [PrehandleSnapshot.cpp:135] ["Add prehandle task split_id=0 limit=7480000000000000FF1F5F728000000000FF0000190000000000FAFFFFFFFFFFFFFF90:7480000000000000FF1F5F728000000000FF0000310000000000FAFFFFFFFFFFFFFF90"] [thread_id=98]
[2023/12/29 09:33:16.520 +08:00] [INFO] [SSTReader.cpp:132] ["Seek cf Default to 7480000000000000FF1F5F728000000000FF0000000000000000FA, split_id=1"] [source=MonoSSTReader] [thread_id=99]
[2023/12/29 09:33:16.520 +08:00] [INFO] [PrehandleSnapshot.cpp:135] ["Add prehandle task split_id=18446744073709551615 limit=:7480000000000000FF1F5F728000000000FF0000190000000000FAFFFFFFFFFFFFFF90"] [thread_id=1]
[2023/12/29 09:33:16.520 +08:00] [INFO] [SSTReader.h:190] ["Open sst file first !2_multi_0 range [7480000000000000FF1F5F728000000000FF0000000000000000FA,7480000000000000FF1F5F728000000000FF00005A0000000000FA] split_id=1"] [source="keyspace=4294967295 table_id=31"] [thread_id=99]
[2023/12/29 09:33:16.520 +08:00] [INFO] [SSTReader.cpp:132] ["Seek cf Write to 7480000000000000FF1F5F728000000000FF0000000000000000FA, split_id=1"] [source=MonoSSTReader] [thread_id=99]
[2023/12/29 09:33:16.520 +08:00] [INFO] [SSTFilesToBlockInputStream.cpp:129] ["Finish Construct MultiSSTReader, write=1 lock=0 default=1 region_id=2 snapshot_index=6"] [source="keyspace=4294967295 table_id=31"] [thread_id=99]
[2023/12/29 09:33:16.520 +08:00] [INFO] [SSTFilesToBlockInputStream.cpp:476] ["Re-Seek after start_raw 7480000000000000FF1F5F728000000000FF0000190000000000FAFFFFFFFFFFFFFF90 start_pk 8000000000000019 to 7480000000000000FF1F5F728000000000FF00001A0000000000FAFFFFFFFFFFFFFF90, current_pk = 800000000000001A, cf=Write, split_id=0, region_id=2"] [source="keyspace=4294967295 table_id=31"] [thread_id=98]
[2023/12/29 09:33:16.520 +08:00] [INFO] [PrehandleSnapshot.cpp:135] ["Add prehandle task split_id=1 limit=7480000000000000FF1F5F728000000000FF0000310000000000FAFFFFFFFFFFFFFF90:7480000000000000FF1F5F728000000000FF0000490000000000FAFFFFFFFFFFFFFF90"] [thread_id=99]
[2023/12/29 09:33:16.520 +08:00] [INFO] [SSTReader.h:190] ["Open sst file first !2_multi_0 range [7480000000000000FF1F5F728000000000FF0000000000000000FA,7480000000000000FF1F5F728000000000FF00005A0000000000FA] split_id=2"] [source="keyspace=4294967295 table_id=31"] [thread_id=100]
[2023/12/29 09:33:16.520 +08:00] [INFO] [SSTReader.cpp:132] ["Seek cf Default to 7480000000000000FF1F5F728000000000FF0000000000000000FA, split_id=2"] [source=MonoSSTReader] [thread_id=100]
[2023/12/29 09:33:16.520 +08:00] [DEBUG] [DMVersionFilterBlockInputStream.h:83] ["Total rows: 0, pass: -nan%, complete pass: -nan%, complete not pass: -nan%, not clean: -nan%, is deleted: -nan%, effective: -nan%, start_ts: 0"] [source="mode=COMPACT"] [thread_id=98]
[2023/12/29 09:33:16.520 +08:00] [INFO] [SSTReader.h:190] ["Open sst file first !2_multi_0 range [7480000000000000FF1F5F728000000000FF0000000000000000FA,7480000000000000FF1F5F728000000000FF00005A0000000000FA] split_id=2"] [source="keyspace=4294967295 table_id=31"] [thread_id=100]
[2023/12/29 09:33:16.520 +08:00] [INFO] [SSTReader.cpp:132] ["Seek cf Write to 7480000000000000FF1F5F728000000000FF0000000000000000FA, split_id=2"] [source=MonoSSTReader] [thread_id=100]
[2023/12/29 09:33:16.521 +08:00] [INFO] [PrehandleSnapshot.cpp:451] ["Finished extra parallel prehandle task limit 7480000000000000FF1F5F728000000000FF0000190000000000FAFFFFFFFFFFFFFF90:7480000000000000FF1F5F728000000000FF0000310000000000FAFFFFFFFFFFFFFF90 write cf 0 lock cf 0 default cf 0 dmfiles 0 error ErrUpdateSchema, split_id=0 region_id=2"] [thread_id=98]
[2023/12/29 09:33:16.521 +08:00] [INFO] [SSTFilesToBlockInputStream.cpp:129] ["Finish Construct MultiSSTReader, write=1 lock=0 default=1 region_id=2 snapshot_index=6"] [source="keyspace=4294967295 table_id=31"] [thread_id=100]
[2023/12/29 09:33:16.521 +08:00] [INFO] [PrehandleSnapshot.cpp:135] ["Add prehandle task split_id=2 limit=7480000000000000FF1F5F728000000000FF0000490000000000FAFFFFFFFFFFFFFF90:"] [thread_id=100]
[2023/12/29 09:33:16.521 +08:00] [INFO] [SSTFilesToBlockInputStream.cpp:476] ["Re-Seek after start_raw 7480000000000000FF1F5F728000000000FF0000310000000000FAFFFFFFFFFFFFFF90 start_pk 8000000000000031 to 7480000000000000FF1F5F728000000000FF0000320000000000FAFFFFFFFFFFFFFF90, current_pk = 8000000000000032, cf=Write, split_id=1, region_id=2"] [source="keyspace=4294967295 table_id=31"] [thread_id=99]
[2023/12/29 09:33:16.521 +08:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:130] ["Transformed snapshot in SSTFile to DTFiles, region=[region_id=2 applied_term=5 applied_index=6] job_type=ApplySnapshot cost_ms=0 rows=0 bytes=0 bytes_on_disk=0 write_cf_keys=0 default_cf_keys=0 lock_cf_keys=0 splid_id=1 dt_files=[files_num=0 ]"] [source="keyspace=4294967295 table_id=31"] [thread_id=99]
[2023/12/29 09:33:16.521 +08:00] [INFO] [SSTFilesToBlockInputStream.cpp:476] ["Re-Seek after start_raw 7480000000000000FF1F5F728000000000FF0000490000000000FAFFFFFFFFFFFFFF90 start_pk 8000000000000049 to 7480000000000000FF1F5F728000000000FF00004A0000000000FAFFFFFFFFFFFFFF90, current_pk = 800000000000004A, cf=Write, split_id=2, region_id=2"] [source="keyspace=4294967295 table_id=31"] [thread_id=100]
[2023/12/29 09:33:16.521 +08:00] [DEBUG] [DMVersionFilterBlockInputStream.h:83] ["Total rows: 0, pass: -nan%, complete pass: -nan%, complete not pass: -nan%, not clean: -nan%, is deleted: -nan%, effective: -nan%, start_ts: 0"] [source="mode=COMPACT"] [thread_id=99]
[2023/12/29 09:33:16.521 +08:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:130] ["Transformed snapshot in SSTFile to DTFiles, region=[region_id=2 applied_term=5 applied_index=6] job_type=ApplySnapshot cost_ms=0 rows=0 bytes=0 bytes_on_disk=0 write_cf_keys=0 default_cf_keys=0 lock_cf_keys=0 splid_id=2 dt_files=[files_num=0 ]"] [source="keyspace=4294967295 table_id=31"] [thread_id=100]
[2023/12/29 09:33:16.521 +08:00] [DEBUG] [DMVersionFilterBlockInputStream.h:83] ["Total rows: 0, pass: -nan%, complete pass: -nan%, complete not pass: -nan%, not clean: -nan%, is deleted: -nan%, effective: -nan%, start_ts: 0"] [source="mode=COMPACT"] [thread_id=100]
[2023/12/29 09:33:16.521 +08:00] [INFO] [PrehandleSnapshot.cpp:451] ["Finished extra parallel prehandle task limit 7480000000000000FF1F5F728000000000FF0000490000000000FAFFFFFFFFFFFFFF90: write cf 0 lock cf 0 default cf 0 dmfiles 0 error ErrUpdateSchema, split_id=2 region_id=2"] [thread_id=100]
[2023/12/29 09:33:16.521 +08:00] [INFO] [PrehandleSnapshot.cpp:451] ["Finished extra parallel prehandle task limit 7480000000000000FF1F5F728000000000FF0000310000000000FAFFFFFFFFFFFFFF90:7480000000000000FF1F5F728000000000FF0000490000000000FAFFFFFFFFFFFFFF90 write cf 0 lock cf 0 default cf 0 dmfiles 0 error ErrUpdateSchema, split_id=1 region_id=2"] [thread_id=99]
[2023/12/29 09:33:16.522 +08:00] [INFO] [SSTFilesToBlockInputStream.cpp:516] ["Reach end for split :7480000000000000FF1F5F728000000000FF0000190000000000FAFFFFFFFFFFFFFF90 current 7480000000000000FF1F5F728000000000FF00001A0000000000FAFFFFFFFFFFFFFF90 pk 800000000000001A end_limit 8000000000000019, cf=Write split_id=18446744073709551615 region_id=2"] [source="keyspace=4294967295 table_id=31"] [thread_id=1]
[2023/12/29 09:33:16.524 +08:00] [INFO] [SSTFilesToBlockInputStream.cpp:516] ["Reach end for split :7480000000000000FF1F5F728000000000FF0000190000000000FAFFFFFFFFFFFFFF90 current 7480000000000000FF1F5F728000000000FF00001A0000000000FAFFFFFFFFFFFFFF90 pk 800000000000001A end_limit 8000000000000019, cf=Default split_id=18446744073709551615 region_id=2"] [source="keyspace=4294967295 table_id=31"] [thread_id=1]
[2023/12/29 09:33:16.524 +08:00] [DEBUG] [SSTFilesToBlockInputStream.cpp:298] ["Done loading all kvpairs, CF=default offset=25 processed_bytes=1325 write_cf_offset=25 region_id=2 split_id=18446744073709551615 snapshot_index=6"] [source="keyspace=4294967295 table_id=31"] [thread_id=1]
[2023/12/29 09:33:16.524 +08:00] [DEBUG] [SSTFilesToBlockInputStream.cpp:298] ["Done loading all kvpairs, CF=lock offset=0 processed_bytes=0 write_cf_offset=25 region_id=2 split_id=18446744073709551615 snapshot_index=6"] [source="keyspace=4294967295 table_id=31"] [thread_id=1]
[2023/12/29 09:33:16.526 +08:00] [DEBUG] [SSTFilesToBlockInputStream.cpp:298] ["Done loading all kvpairs, CF=default offset=25 processed_bytes=1325 write_cf_offset=25 region_id=2 split_id=18446744073709551615 snapshot_index=6"] [source="keyspace=4294967295 table_id=31"] [thread_id=1]
[2023/12/29 09:33:16.526 +08:00] [DEBUG] [SSTFilesToBlockInputStream.cpp:298] ["Done loading all kvpairs, CF=lock offset=0 processed_bytes=0 write_cf_offset=25 region_id=2 split_id=18446744073709551615 snapshot_index=6"] [source="keyspace=4294967295 table_id=31"] [thread_id=1]
[2023/12/29 09:33:16.526 +08:00] [WARN] [StoragePool.cpp:985] ["The DTFile is already exists, continute to acquire another ID. [call=std::tuple<String, PageIdU64> DB::DM::DeltaMergeStore::preAllocateIngestFile()][path=<mock for existed path>] [id=1]"] [source=db_1.t_31] [thread_id=1]
[2023/12/29 09:33:16.534 +08:00] [DEBUG] [SSTFilesToDTFilesOutputStream.cpp:202] ["Create new DTFile for snapshot data, region_id=2 file_idx=0 file=/tmp-memfs/tiflash-tests/tmp/20079/data/t_31/stable/.tmp.dmf_2"] [source="keyspace=4294967295 table_id=31"] [thread_id=1]
[2023/12/29 09:33:16.537 +08:00] [DEBUG] [PathPool.cpp:553] ["added new dtfile. [id=2] [path=/tmp-memfs/tiflash-tests/tmp/20079/data/t_31] [real_size=1445] [reported_size=249]"] [thread_id=1]
[2023/12/29 09:33:16.538 +08:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:238] ["Finished writing DTFile from snapshot data, region=[region_id=2 applied_term=5 applied_index=6] file_idx=0 file_rows=25 file_bytes=625 data_range=[1,26) file_bytes_on_disk=249 file=/tmp-memfs/tiflash-tests/tmp/20079/data/t_31/stable/dmf_2"] [source="keyspace=4294967295 table_id=31"] [thread_id=1]
[2023/12/29 09:33:16.538 +08:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:130] ["Transformed snapshot in SSTFile to DTFiles, region=[region_id=2 applied_term=5 applied_index=6] job_type=ApplySnapshot cost_ms=17 rows=25 bytes=625 bytes_on_disk=249 write_cf_keys=25 default_cf_keys=25 lock_cf_keys=0 splid_id=18446744073709551615 dt_files=[files_num=1 dmf_2]"] [source="keyspace=4294967295 table_id=31"] [thread_id=1]
[2023/12/29 09:33:16.539 +08:00] [DEBUG] [DMVersionFilterBlockInputStream.h:83] ["Total rows: 25, pass: 100.00%, complete pass: 100.00%, complete not pass: 0.00%, not clean: 0.00%, is deleted: 0.00%, effective: 100.00%, start_ts: 0"] [source="mode=COMPACT"] [thread_id=1]
[2023/12/29 09:33:16.539 +08:00] [INFO] [PrehandleSnapshot.cpp:565] ["Finished extra parallel prehandle task limit :7480000000000000FF1F5F728000000000FF0000190000000000FAFFFFFFFFFFFFFF90 write cf 25 lock cf 0 default cf 25 dmfiles 0 error ErrUpdateSchema, split_id=18446744073709551615, region_id=2"] [thread_id=1]
[2023/12/29 09:33:16.539 +08:00] [DEBUG] [PrehandleSnapshot.cpp:572] ["Try fetch prehandle task split_id=0, region_id=2"] [thread_id=1]
[2023/12/29 09:33:16.539 +08:00] [DEBUG] [PrehandleSnapshot.cpp:572] ["Try fetch prehandle task split_id=1, region_id=2"] [thread_id=1]
[2023/12/29 09:33:16.539 +08:00] [DEBUG] [PrehandleSnapshot.cpp:572] ["Try fetch prehandle task split_id=2, region_id=2"] [thread_id=1]
[2023/12/29 09:33:16.539 +08:00] [INFO] [AsyncTasks.h:56] ["Pending 0 tasks when destructing"] [thread_id=1]
[2023/12/29 09:33:16.539 +08:00] [INFO] [PrehandleSnapshot.cpp:761] ["Decoding Region snapshot data meet error, sync schema and try to decode again [region_id=2 applied_term=5 applied_index=6] [error=]"] [thread_id=1]
[2023/12/29 09:33:16.539 +08:00] [INFO] [TiDBSchemaSyncer.cpp:234] ["Sync table schema begin, table_id=31"] [source="keyspace=4294967295"] [thread_id=1]
[2023/12/29 09:33:16.540 +08:00] [INFO] [SchemaBuilder.cpp:1493] ["Alter table db_1.t846930886 begin, database_id=1 table_id=31"] [source="keyspace=4294967295"] [thread_id=1]
[2023/12/29 09:33:16.541 +08:00] [DEBUG] [StorageDeltaMerge.cpp:1521] ["Update table_info: {\"cols\":[{\"comment\":\"\",\"default\":null,\"default_bit\":null,\"id\":1,\"name\":{\"L\":\"a\",\"O\":\"a\"},\"offset\":-1,\"origin_default\":null,\"state\":0,\"type\":{\"Charset\":null,\"Collate\":null,\"Decimal\":0,\"Elems\":null,\"Flag\":4097,\"Flen\":0,\"Tp\":8}}],\"comment\":\"Mocked.\",\"id\":31,\"index_info\":[],\"is_common_handle\":false,\"keyspace_id\":4294967295,\"name\":{\"L\":\"t846930886\",\"O\":\"t846930886\"},\"partition\":null,\"pk_is_handle\":false,\"schema_version\":-1,\"state\":0,\"tiflash_replica\":{\"Count\":0},\"update_timestamp\":1703813596450655} => {\"cols\":[{\"comment\":\"\",\"default\":null,\"default_bit\":null,\"id\":1,\"name\":{\"L\":\"a\",\"O\":\"a\"},\"offset\":-1,\"origin_default\":null,\"state\":0,\"type\":{\"Charset\":null,\"Collate\":null,\"Decimal\":0,\"Elems\":null,\"Flag\":4097,\"Flen\":0,\"Tp\":8}}],\"comment\":\"Mocked.\",\"id\":31,\"index_info\":[],\"is_common_handle\":false,\"keyspace_id\":4294967295,\"name\":{\"L\":\"t846930886\",\"O\":\"t846930886\"},\"partition\":null,\"pk_is_handle\":false,\"schema_version\":-1,\"state\":0,\"tiflash_replica\":{\"Count\":0},\"update_timestamp\":1703813596450655}"] [source=db_1.t_31] [thread_id=1]
[2023/12/29 09:33:16.544 +08:00] [INFO] [SchemaBuilder.cpp:1508] ["Alter table db_1.t846930886 end, database_id=1 table_id=31"] [source="keyspace=4294967295"] [thread_id=1]
[2023/12/29 09:33:16.544 +08:00] [INFO] [TiDBSchemaSyncer.cpp:243] ["Sync table schema end, table_id=31"] [source="keyspace=4294967295"] [thread_id=1]
[2023/12/29 09:33:16.544 +08:00] [DEBUG] [PartitionStreams.cpp:451] ["Get schema, keyspace=4294967295 table_id=31"] [source="std::tuple<TableLockHolder, std::shared_ptr<StorageDeltaMerge>, DecodingStorageSchemaSnapshotConstPtr> DB::AtomicGetStorageSchema(const DB::RegionPtr &, DB::TMTContext &)"] [thread_id=1]
[2023/12/29 09:33:16.544 +08:00] [INFO] [SSTReader.h:190] ["Open sst file first !2_multi_0 range [7480000000000000FF1F5F728000000000FF0000000000000000FA,7480000000000000FF1F5F728000000000FF00005A0000000000FA] split_id=18446744073709551615"] [source="keyspace=4294967295 table_id=31"] [thread_id=1]
[2023/12/29 09:33:16.544 +08:00] [INFO] [SSTReader.cpp:132] ["Seek cf Default to 7480000000000000FF1F5F728000000000FF0000000000000000FA, split_id=18446744073709551615"] [source=MonoSSTReader] [thread_id=1]
[2023/12/29 09:33:16.544 +08:00] [INFO] [SSTReader.h:190] ["Open sst file first !2_multi_0 range [7480000000000000FF1F5F728000000000FF0000000000000000FA,7480000000000000FF1F5F728000000000FF00005A0000000000FA] split_id=18446744073709551615"] [source="keyspace=4294967295 table_id=31"] [thread_id=1]
[2023/12/29 09:33:16.544 +08:00] [INFO] [SSTReader.cpp:132] ["Seek cf Write to 7480000000000000FF1F5F728000000000FF0000000000000000FA, split_id=18446744073709551615"] [source=MonoSSTReader] [thread_id=1]
[2023/12/29 09:33:16.544 +08:00] [INFO] [SSTFilesToBlockInputStream.cpp:129] ["Finish Construct MultiSSTReader, write=1 lock=0 default=1 region_id=2 snapshot_index=6"] [source="keyspace=4294967295 table_id=31"] [thread_id=1]
[2023/12/29 09:33:16.545 +08:00] [INFO] [PrehandleSnapshot.cpp:388] ["getSplitKey result 7480000000000000FF1F5F728000000000FF0000190000000000FAFFFFFFFFFFFFFF90:7480000000000000FF1F5F728000000000FF0000310000000000FAFFFFFFFFFFFFFF90:7480000000000000FF1F5F728000000000FF0000490000000000FAFFFFFFFFFFFFFF90, total_concurrency=4 ongoing=1 total_split_parts=4 split_keys=3 region_range=[7480000000000000FF1F5F728000000000FF0000000000000000FA,7480000000000000FF1F5F728000000000FF00005A0000000000FA] approx_bytes=1980 region_id=2"] [thread_id=1]
[2023/12/29 09:33:16.545 +08:00] [DEBUG] [PrehandleSnapshot.cpp:78] ["Prehandle resource meet, limit=4, current=4, region_id=2"] [source=PreHandlingTrace] [thread_id=1]
[2023/12/29 09:33:16.545 +08:00] [INFO] [PrehandleSnapshot.cpp:511] ["Parallel prehandling for single big region, range=[7480000000000000FF1F5F728000000000FF0000000000000000FA,7480000000000000FF1F5F728000000000FF00005A0000000000FA], split keys=3, region_id=2"] [thread_id=1]
[2023/12/29 09:33:16.545 +08:00] [INFO] [PrehandleSnapshot.cpp:135] ["Add prehandle task split_id=18446744073709551615 limit=:7480000000000000FF1F5F728000000000FF0000190000000000FAFFFFFFFFFFFFFF90"] [thread_id=1]
[2023/12/29 09:33:16.545 +08:00] [INFO] [SSTReader.h:190] ["Open sst file first !2_multi_0 range [7480000000000000FF1F5F728000000000FF0000000000000000FA,7480000000000000FF1F5F728000000000FF00005A0000000000FA] split_id=0"] [source="keyspace=4294967295 table_id=31"] [thread_id=98]
[2023/12/29 09:33:16.545 +08:00] [INFO] [SSTReader.h:190] ["Open sst file first !2_multi_0 range [7480000000000000FF1F5F728000000000FF0000000000000000FA,7480000000000000FF1F5F728000000000FF00005A0000000000FA] split_id=1"] [source="keyspace=4294967295 table_id=31"] [thread_id=100]
[2023/12/29 09:33:16.545 +08:00] [INFO] [SSTReader.cpp:132] ["Seek cf Default to 7480000000000000FF1F5F728000000000FF0000000000000000FA, split_id=0"] [source=MonoSSTReader] [thread_id=98]
[2023/12/29 09:33:16.545 +08:00] [INFO] [SSTReader.cpp:132] ["Seek cf Default to 7480000000000000FF1F5F728000000000FF0000000000000000FA, split_id=1"] [source=MonoSSTReader] [thread_id=100]
[2023/12/29 09:33:16.545 +08:00] [INFO] [SSTReader.h:190] ["Open sst file first !2_multi_0 range [7480000000000000FF1F5F728000000000FF0000000000000000FA,7480000000000000FF1F5F728000000000FF00005A0000000000FA] split_id=0"] [source="keyspace=4294967295 table_id=31"] [thread_id=98]
[2023/12/29 09:33:16.545 +08:00] [INFO] [SSTReader.h:190] ["Open sst file first !2_multi_0 range [7480000000000000FF1F5F728000000000FF0000000000000000FA,7480000000000000FF1F5F728000000000FF00005A0000000000FA] split_id=1"] [source="keyspace=4294967295 table_id=31"] [thread_id=100]
[2023/12/29 09:33:16.545 +08:00] [INFO] [SSTReader.cpp:132] ["Seek cf Write to 7480000000000000FF1F5F728000000000FF0000000000000000FA, split_id=0"] [source=MonoSSTReader] [thread_id=98]
[2023/12/29 09:33:16.545 +08:00] [INFO] [SSTReader.cpp:132] ["Seek cf Write to 7480000000000000FF1F5F728000000000FF0000000000000000FA, split_id=1"] [source=MonoSSTReader] [thread_id=100]
[2023/12/29 09:33:16.545 +08:00] [INFO] [SSTFilesToBlockInputStream.cpp:129] ["Finish Construct MultiSSTReader, write=1 lock=0 default=1 region_id=2 snapshot_index=6"] [source="keyspace=4294967295 table_id=31"] [thread_id=98]
[2023/12/29 09:33:16.545 +08:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:130] ["Transformed snapshot in SSTFile to DTFiles, region=[region_id=2 applied_term=5 applied_index=6] job_type=ApplySnapshot cost_ms=0 rows=0 bytes=0 bytes_on_disk=0 write_cf_keys=0 default_cf_keys=0 lock_cf_keys=0 splid_id=18446744073709551615 dt_files=[files_num=0 ]"] [source="keyspace=4294967295 table_id=31"] [thread_id=1]
[2023/12/29 09:33:16.545 +08:00] [INFO] [SSTFilesToBlockInputStream.cpp:129] ["Finish Construct MultiSSTReader, write=1 lock=0 default=1 region_id=2 snapshot_index=6"] [source="keyspace=4294967295 table_id=31"] [thread_id=100]
[2023/12/29 09:33:16.545 +08:00] [INFO] [PrehandleSnapshot.cpp:135] ["Add prehandle task split_id=0 limit=7480000000000000FF1F5F728000000000FF0000190000000000FAFFFFFFFFFFFFFF90:7480000000000000FF1F5F728000000000FF0000310000000000FAFFFFFFFFFFFFFF90"] [thread_id=98]
[2023/12/29 09:33:16.545 +08:00] [DEBUG] [DMVersionFilterBlockInputStream.h:83] ["Total rows: 0, pass: -nan%, complete pass: -nan%, complete not pass: -nan%, not clean: -nan%, is deleted: -nan%, effective: -nan%, start_ts: 0"] [source="mode=COMPACT"] [thread_id=1]
[2023/12/29 09:33:16.545 +08:00] [INFO] [PrehandleSnapshot.cpp:135] ["Add prehandle task split_id=1 limit=7480000000000000FF1F5F728000000000FF0000310000000000FAFFFFFFFFFFFFFF90:7480000000000000FF1F5F728000000000FF0000490000000000FAFFFFFFFFFFFFFF90"] [thread_id=100]
[2023/12/29 09:33:16.545 +08:00] [INFO] [PrehandleSnapshot.cpp:565] ["Finished extra parallel prehandle task limit :7480000000000000FF1F5F728000000000FF0000190000000000FAFFFFFFFFFFFFFF90 write cf 0 lock cf 0 default cf 0 dmfiles 0 error ErrUpdateSchema, split_id=18446744073709551615, region_id=2"] [thread_id=1]
[2023/12/29 09:33:16.545 +08:00] [DEBUG] [PrehandleSnapshot.cpp:572] ["Try fetch prehandle task split_id=0, region_id=2"] [thread_id=1]
[2023/12/29 09:33:16.545 +08:00] [INFO] [SSTReader.h:190] ["Open sst file first !2_multi_0 range [7480000000000000FF1F5F728000000000FF0000000000000000FA,7480000000000000FF1F5F728000000000FF00005A0000000000FA] split_id=2"] [source="keyspace=4294967295 table_id=31"] [thread_id=99]
[2023/12/29 09:33:16.545 +08:00] [INFO] [SSTFilesToBlockInputStream.cpp:476] ["Re-Seek after start_raw 7480000000000000FF1F5F728000000000FF0000190000000000FAFFFFFFFFFFFFFF90 start_pk 8000000000000019 to 7480000000000000FF1F5F728000000000FF00001A0000000000FAFFFFFFFFFFFFFF90, current_pk = 800000000000001A, cf=Write, split_id=0, region_id=2"] [source="keyspace=4294967295 table_id=31"] [thread_id=98]
[2023/12/29 09:33:16.545 +08:00] [INFO] [SSTFilesToBlockInputStream.cpp:476] ["Re-Seek after start_raw 7480000000000000FF1F5F728000000000FF0000310000000000FAFFFFFFFFFFFFFF90 start_pk 8000000000000031 to 7480000000000000FF1F5F728000000000FF0000320000000000FAFFFFFFFFFFFFFF90, current_pk = 8000000000000032, cf=Write, split_id=1, region_id=2"] [source="keyspace=4294967295 table_id=31"] [thread_id=100]
[2023/12/29 09:33:16.546 +08:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:130] ["Transformed snapshot in SSTFile to DTFiles, region=[region_id=2 applied_term=5 applied_index=6] job_type=ApplySnapshot cost_ms=0 rows=0 bytes=0 bytes_on_disk=0 write_cf_keys=0 default_cf_keys=0 lock_cf_keys=0 splid_id=0 dt_files=[files_num=0 ]"] [source="keyspace=4294967295 table_id=31"] [thread_id=98]
[2023/12/29 09:33:16.546 +08:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:130] ["Transformed snapshot in SSTFile to DTFiles, region=[region_id=2 applied_term=5 applied_index=6] job_type=ApplySnapshot cost_ms=0 rows=0 bytes=0 bytes_on_disk=0 write_cf_keys=0 default_cf_keys=0 lock_cf_keys=0 splid_id=1 dt_files=[files_num=0 ]"] [source="keyspace=4294967295 table_id=31"] [thread_id=100]
[2023/12/29 09:33:16.546 +08:00] [DEBUG] [DMVersionFilterBlockInputStream.h:83] ["Total rows: 0, pass: -nan%, complete pass: -nan%, complete not pass: -nan%, not clean: -nan%, is deleted: -nan%, effective: -nan%, start_ts: 0"] [source="mode=COMPACT"] [thread_id=98]
[2023/12/29 09:33:16.546 +08:00] [DEBUG] [DMVersionFilterBlockInputStream.h:83] ["Total rows: 0, pass: -nan%, complete pass: -nan%, complete not pass: -nan%, not clean: -nan%, is deleted: -nan%, effective: -nan%, start_ts: 0"] [source="mode=COMPACT"] [thread_id=100]
[2023/12/29 09:33:16.546 +08:00] [INFO] [SSTReader.cpp:132] ["Seek cf Default to 7480000000000000FF1F5F728000000000FF0000000000000000FA, split_id=2"] [source=MonoSSTReader] [thread_id=99]
[2023/12/29 09:33:16.546 +08:00] [INFO] [PrehandleSnapshot.cpp:451] ["Finished extra parallel prehandle task limit 7480000000000000FF1F5F728000000000FF0000190000000000FAFFFFFFFFFFFFFF90:7480000000000000FF1F5F728000000000FF0000310000000000FAFFFFFFFFFFFFFF90 write cf 0 lock cf 0 default cf 0 dmfiles 0 error ErrUpdateSchema, split_id=0 region_id=2"] [thread_id=98]
[2023/12/29 09:33:16.546 +08:00] [INFO] [PrehandleSnapshot.cpp:451] ["Finished extra parallel prehandle task limit 7480000000000000FF1F5F728000000000FF0000310000000000FAFFFFFFFFFFFFFF90:7480000000000000FF1F5F728000000000FF0000490000000000FAFFFFFFFFFFFFFF90 write cf 0 lock cf 0 default cf 0 dmfiles 0 error ErrUpdateSchema, split_id=1 region_id=2"] [thread_id=100]
[2023/12/29 09:33:16.546 +08:00] [DEBUG] [PrehandleSnapshot.cpp:572] ["Try fetch prehandle task split_id=1, region_id=2"] [thread_id=1]
[2023/12/29 09:33:16.546 +08:00] [DEBUG] [PrehandleSnapshot.cpp:572] ["Try fetch prehandle task split_id=2, region_id=2"] [thread_id=1]
[2023/12/29 09:33:16.546 +08:00] [INFO] [SSTReader.h:190] ["Open sst file first !2_multi_0 range [7480000000000000FF1F5F728000000000FF0000000000000000FA,7480000000000000FF1F5F728000000000FF00005A0000000000FA] split_id=2"] [source="keyspace=4294967295 table_id=31"] [thread_id=99]
[2023/12/29 09:33:16.546 +08:00] [INFO] [SSTReader.cpp:132] ["Seek cf Write to 7480000000000000FF1F5F728000000000FF0000000000000000FA, split_id=2"] [source=MonoSSTReader] [thread_id=99]
[2023/12/29 09:33:16.546 +08:00] [INFO] [SSTFilesToBlockInputStream.cpp:129] ["Finish Construct MultiSSTReader, write=1 lock=0 default=1 region_id=2 snapshot_index=6"] [source="keyspace=4294967295 table_id=31"] [thread_id=99]
[2023/12/29 09:33:16.546 +08:00] [INFO] [PrehandleSnapshot.cpp:135] ["Add prehandle task split_id=2 limit=7480000000000000FF1F5F728000000000FF0000490000000000FAFFFFFFFFFFFFFF90:"] [thread_id=99]
[2023/12/29 09:33:16.548 +08:00] [INFO] [SSTFilesToBlockInputStream.cpp:476] ["Re-Seek after start_raw 7480000000000000FF1F5F728000000000FF0000490000000000FAFFFFFFFFFFFFFF90 start_pk 8000000000000049 to 7480000000000000FF1F5F728000000000FF00004A0000000000FAFFFFFFFFFFFFFF90, current_pk = 800000000000004A, cf=Write, split_id=2, region_id=2"] [source="keyspace=4294967295 table_id=31"] [thread_id=99]
[2023/12/29 09:33:16.548 +08:00] [INFO] [SSTFilesToDTFilesOutputStream.cpp:130] ["Transformed snapshot in SSTFile to DTFiles, region=[region_id=2 applied_term=5 applied_index=6] job_type=ApplySnapshot cost_ms=0 rows=0 bytes=0 bytes_on_disk=0 write_cf_keys=0 default_cf_keys=0 lock_cf_keys=0 splid_id=2 dt_files=[files_num=0 ]"] [source="keyspace=4294967295 table_id=31"] [thread_id=99]
[2023/12/29 09:33:16.548 +08:00] [DEBUG] [DMVersionFilterBlockInputStream.h:83] ["Total rows: 0, pass: -nan%, complete pass: -nan%, complete not pass: -nan%, not clean: -nan%, is deleted: -nan%, effective: -nan%, start_ts: 0"] [source="mode=COMPACT"] [thread_id=99]
[2023/12/29 09:33:16.549 +08:00] [INFO] [PrehandleSnapshot.cpp:451] ["Finished extra parallel prehandle task limit 7480000000000000FF1F5F728000000000FF0000490000000000FAFFFFFFFFFFFFFF90: write cf 0 lock cf 0 default cf 0 dmfiles 0 error ErrUpdateSchema, split_id=2 region_id=2"] [thread_id=99]
[2023/12/29 09:33:16.549 +08:00] [INFO] [AsyncTasks.h:56] ["Pending 0 tasks when destructing"] [thread_id=1]
[2023/12/29 09:33:16.549 +08:00] [INFO] [PrehandleSnapshot.cpp:880] ["After prehandle, orphan keys remains=0 removed=0 ongoing_prehandle=0 region_id=2"] [thread_id=1]
/home/jenkins/agent/workspace/tiflash-build-common/tiflash/dbms/src/Storages/KVStore/tests/gtest_raftstore_v2.cpp:804: Failure
Failed
Code: 9009. DB::Exception: keyspace=4294967295 physical_table_id=31: (while preHandleSnapshot region_id=2, index=6, term=5)

Stack trace:

      0x11355fae StackTrace::StackTrace() [gtests_dbms+288710574]
       0x490bc22 DB::Exception::Exception(std::__1::basic_string<char, std::__1::char_traits<char>, std::__1::allocator<char> > const&, int) [gtests_dbms+76594210]
       0xdfdce63 DB::KVStore::preHandleSSTsToDTFiles(std::__1::shared_ptr<DB::Region>, DB::SSTViewVec, unsigned long, unsigned long, DB::DM::FileConvertJobType, DB::TMTContext&) [gtests_dbms+234737251]
       0xdfdb893 DB::KVStore::preHandleSnapshotToFiles(std::__1::shared_ptr<DB::Region>, DB::SSTViewVec, unsigned long, unsigned long, std::__1::optional<unsigned long>, DB::TMTContext&) [gtests_dbms+234731667]
       0xeef49c5 DB::MockRaftStoreProxy::snapshot(DB::KVStore&, DB::TMTContext&, unsigned long, std::__1::vector<DB::MockSSTGenerator, std::__1::allocator<DB::MockSSTGenerator> >&&, unsigned long, unsigned long, std::__1::optional<unsigned long>, bool) [gtests_dbms+250563013]
       0x77be1f8 DB::tests::RegionKVStoreV2Test_KVStoreSingleSnap4_Test::TestBody() [gtests_dbms+125559288]
       0xe172a7b void testing::internal::HandleSehExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::*)(), char const*) [gtests_dbms+236399227]
       0xe15fe8a void testing::internal::HandleExceptionsInMethodIfSupported<testing::Test, void>(testing::Test*, void (testing::Test::*)(), char const*) [gtests_dbms+236322442]
       0xe1453dc testing::Test::Run() [gtests_dbms+236213212]
       0xe145efa testing::TestInfo::Run() [gtests_dbms+236216058]
       0xe1464b3 testing::TestCase::Run() [gtests_dbms+236217523]
       0xe150663 testing::internal::UnitTestImpl::RunAllTests() [gtests_dbms+236258915]
       0xe1762ab bool testing::internal::HandleSehExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool>(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::*)(), char const*) [gtests_dbms+236413611]
       0xe161e8a bool testing::internal::HandleExceptionsInMethodIfSupported<testing::internal::UnitTestImpl, bool>(testing::internal::UnitTestImpl*, bool (testing::internal::UnitTestImpl::*)(), char const*) [gtests_dbms+236330634]
       0xe150376 testing::UnitTest::Run() [gtests_dbms+236258166]
       0x7dc6711 RUN_ALL_TESTS() [gtests_dbms+131884817]
       0x7dc2744 main [gtests_dbms+131868484]
  0x7fd3c9d9e555 __libc_start_main [libc.so.6+140629]
       0x4900ce9 <unknown symbol> [gtests_dbms+76549353]

[2023/12/29 09:33:16.729 +08:00] [INFO] [KVStore.cpp:654] ["Destroy KVStore"] [thread_id=1]
�[0;31m[  FAILED  ] �[mRegionKVStoreV2Test.KVStoreSingleSnap4 (286 ms)

4. What is your TiFlash version? (Required)

master
@Lloyd-Pottiger
Copy link
Contributor

https://ci.pingcap.net/blue/organizations/jenkins/tiflash-ghpr-unit-tests/detail/tiflash-ghpr-unit-tests/12428/pipeline

@CalvinNeo
Copy link
Member 

            if (result.error == PrehandleTransformStatus::ErrUpdateSchema)
            {
                // It will be thrown in `SSTFilesToBlockInputStream`.
                // The schema of decoding region data has been updated, need to clear and recreate another stream for writing DTFile(s)
                new_region->clearAllData();

                if (force_decode)
                {
                    // Can not decode data with `force_decode == true`, must be something wrong
                    throw Exception(
                        fmt::format("Force decode failed {}", result.extra_msg),
                        ErrorCodes::REGION_DATA_SCHEMA_UPDATED);
                }

@CalvinNeo CalvinNeo mentioned this issue Jan 2, 2024
Merged
12 tasks
@ti-chi-bot ti-chi-bot bot closed this as completed in #8614 Jan 3, 2024
ti-chi-bot bot pushed a commit that referenced this issue Jan 3, 2024
@CalvinNeo
KVStore: introduce flexible region format (#8614)
7273bbc 
close #8590, close #8624, close #8625
@CalvinNeo
Copy link
Member

Because prehandle_result is not reset after retry

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@CalvinNeo CalvinNeo

Labels
component/storage severity/moderate type/bug The issue is confirmed as a bug.
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

KVStore: introduce flexible region format CalvinNeo/tiflash
3 participants
@JaySon-Huang @CalvinNeo @Lloyd-Pottiger