[Bug]: ut TestCompaction2 failed

[sukki37]

Is there an existing issue for the same bug?

• [X] I have checked the existing issues.

Branch Name

main

Commit ID

during one pr

Other Environment Information

- Hardware parameters:
- OS type:
- Others:

Actual Behavior

https://github.com/matrixorigin/matrixone/actions/runs/9015017541/job/24768878410?pr=15945

2024-05-09T09:38:38.2157858Z === RUN   TestCompaction2
2024-05-09T09:38:38.2158557Z 2024/05/09 09:23:23.116108 +0000 INFO db/open.go:71 open-tae {"operation": "Start", "operand": "open"}
2024-05-09T09:38:38.2159958Z 2024/05/09 09:23:23.116261 +0000 INFO db/open.go:65 mergeblocks options {"toml": "CNMergeMemControlHint = 8589934592\nCNTakeOverAll = false\nCNTakeOverExceed = 83886080000\nCNStandaloneTake = false\n", "standalone": false}
2024-05-09T09:38:38.2161658Z 2024/05/09 09:23:23.126538 +0000 INFO db/open.go:171 open-tae {"operation": "replay", "operand": "checkpoints", "cost": "29.165µs", "checkpointed": "0-0"}
2024-05-09T09:38:38.2163217Z 2024/05/09 09:23:23.126654 +0000 INFO batchstoredriver/store.go:278 open-tae {"operation": "replay", "operand": "wal", "backend": "batchstore", "apply cost": "0s", "read cost": "8.947µs"}
2024-05-09T09:38:38.2164938Z 2024/05/09 09:23:23.126762 +0000 INFO db/replay.go:108 open-tae {"operation": "replay", "operand": "wal", "apply logentries cost": "0s", "read count": 0, "apply count": 0}
2024-05-09T09:38:38.2165989Z 2024/05/09 09:23:23.126829 +0000 INFO txnbase/txnmgr.go:152 init ts to 0-0
2024-05-09T09:38:38.2166922Z 2024/05/09 09:23:23.126884 +0000 INFO logtail/storage_usage.go:650 [storage usage] replay: {"remove old deleted db/tbl": "", "delayed tbl": 0}
2024-05-09T09:38:38.2168153Z 2024/05/09 09:23:23.126965 +0000 INFO db/open.go:181 open-tae {"operation": "replay", "operand": "wal", "cost": "349.743µs"}
2024-05-09T09:38:38.2169348Z 2024/05/09 09:23:23.127264 +0000 INFO db/open.go:82 open-tae {"operation": "End", "operand": "open", "cost": "11.086719ms", "err": null}
2024-05-09T09:38:38.2170226Z 2024/05/09 09:23:23.127360 +0000 INFO db/open.go:294 tae metrics task started
2024-05-09T09:38:38.2171465Z 2024/05/09 09:23:23.127905 +0000 INFO dbutils/runtime.go:113 VectorPool[trasient-vector-pool][0/512]: FixSizedVec[0/307] VarlenVec[0/205], Reset/Hit/totalStats:[0/(0,0)0/0]
2024-05-09T09:38:38.2172933Z VectorPool[small-vector-pool][0/10240]: FixSizedVec[0/6144] VarlenVec[0/4096], Reset/Hit/totalStats:[0/(6,0)6/6]
2024-05-09T09:38:38.2173886Z 2024/05/09 09:23:23.127978 +0000 INFO gc/diskcleaner.go:55 JobFactory is start
2024-05-09T09:38:38.2174570Z 2024/05/09 09:23:23.128066 +0000 INFO db/open.go:260 LogtailStats: Compact[0|0]
2024-05-09T09:38:38.2175819Z 2024/05/09 09:23:23.137776 +0000 INFO dbutils/mem.go:133 HeapInfo:TotalAlloc:11803MB Sys:205MB HeapAlloc:95MB HeapSys:188MB HeapIdle:88MB HeapReleased:33MB HeapInuse:99MB NextGC:141MB NumGC:250 PauseNs:362527211
2024-05-09T09:38:38.2177429Z 2024/05/09 09:23:23.138008 +0000 INFO checkpoint/runner.go:930 [flushtabletail] scan result: pressure 3.4365803003311157e-07, totalsize 369B
2024-05-09T09:38:38.2178914Z 2024/05/09 09:23:23.138604 +0000 INFO dbutils/runtime.go:113 VectorPool[trasient-vector-pool][0/512]: FixSizedVec[0/307] VarlenVec[0/205], Reset/Hit/totalStats:[0/(0,0)0/0]
2024-05-09T09:38:38.2180236Z VectorPool[small-vector-pool][0/10240]: FixSizedVec[0/6144] VarlenVec[0/4096], Reset/Hit/totalStats:[0/(14,1)15/15]
2024-05-09T09:38:38.2181081Z 2024/05/09 09:23:23.138679 +0000 INFO gc/diskcleaner.go:55 JobFactory is start
2024-05-09T09:38:38.2181776Z 2024/05/09 09:23:23.138750 +0000 INFO db/open.go:260 LogtailStats: Compact[0|0]
2024-05-09T09:38:38.2183011Z 2024/05/09 09:23:23.147296 +0000 INFO dbutils/mem.go:133 HeapInfo:TotalAlloc:11803MB Sys:205MB HeapAlloc:95MB HeapSys:188MB HeapIdle:88MB HeapReleased:36MB HeapInuse:99MB NextGC:141MB NumGC:250 PauseNs:362527211
2024-05-09T09:38:38.2184615Z 2024/05/09 09:23:23.147477 +0000 INFO checkpoint/runner.go:930 [flushtabletail] scan result: pressure 3.4365803003311157e-07, totalsize 369B
2024-05-09T09:38:38.2186102Z 2024/05/09 09:23:23.148196 +0000 INFO dbutils/runtime.go:113 VectorPool[trasient-vector-pool][0/512]: FixSizedVec[0/307] VarlenVec[0/205], Reset/Hit/totalStats:[0/(0,0)0/0]
2024-05-09T09:38:38.2187422Z VectorPool[small-vector-pool][0/10240]: FixSizedVec[0/6144] VarlenVec[0/4096], Reset/Hit/totalStats:[0/(14,1)15/15]
2024-05-09T09:38:38.2188262Z 2024/05/09 09:23:23.148254 +0000 INFO gc/diskcleaner.go:55 JobFactory is start
2024-05-09T09:38:38.2188951Z 2024/05/09 09:23:23.148323 +0000 INFO db/open.go:260 LogtailStats: Compact[0|0]
2024-05-09T09:38:38.2190202Z 2024/05/09 09:23:23.157832 +0000 INFO dbutils/mem.go:133 HeapInfo:TotalAlloc:11803MB Sys:205MB HeapAlloc:95MB HeapSys:188MB HeapIdle:88MB HeapReleased:36MB HeapInuse:99MB NextGC:141MB NumGC:250 PauseNs:362527211
2024-05-09T09:38:38.2191802Z 2024/05/09 09:23:23.158018 +0000 INFO checkpoint/runner.go:930 [flushtabletail] scan result: pressure 3.4365803003311157e-07, totalsize 369B
2024-05-09T09:38:38.2193279Z 2024/05/09 09:23:23.158725 +0000 INFO dbutils/runtime.go:113 VectorPool[trasient-vector-pool][0/512]: FixSizedVec[0/307] VarlenVec[0/205], Reset/Hit/totalStats:[0/(0,0)0/0]
2024-05-09T09:38:38.2194594Z VectorPool[small-vector-pool][0/10240]: FixSizedVec[0/6144] VarlenVec[0/4096], Reset/Hit/totalStats:[0/(14,1)15/15]
2024-05-09T09:38:38.2195417Z 2024/05/09 09:23:23.158797 +0000 INFO gc/diskcleaner.go:55 JobFactory is start
2024-05-09T09:38:38.2196101Z 2024/05/09 09:23:23.158865 +0000 INFO db/open.go:260 LogtailStats: Compact[0|0]
2024-05-09T09:38:38.2197175Z 2024/05/09 09:23:23.167375 +0000 INFO checkpoint/runner.go:930 [flushtabletail] scan result: pressure 3.4365803003311157e-07, totalsize 369B
2024-05-09T09:38:38.2198660Z 2024/05/09 09:23:23.167583 +0000 INFO dbutils/mem.go:133 HeapInfo:TotalAlloc:11803MB Sys:205MB HeapAlloc:74MB HeapSys:188MB HeapIdle:109MB HeapReleased:36MB HeapInuse:78MB NextGC:147MB NumGC:251 PauseNs:362567235
2024-05-09T09:38:38.2200419Z 2024/05/09 09:23:23.168897 +0000 INFO dbutils/runtime.go:113 VectorPool[trasient-vector-pool][0/512]: FixSizedVec[0/307] VarlenVec[0/205], Reset/Hit/totalStats:[0/(0,0)0/0]
2024-05-09T09:38:38.2201736Z VectorPool[small-vector-pool][0/10240]: FixSizedVec[0/6144] VarlenVec[0/4096], Reset/Hit/totalStats:[0/(14,1)15/15]
2024-05-09T09:38:38.2202561Z 2024/05/09 09:23:23.168996 +0000 INFO gc/diskcleaner.go:55 JobFactory is start
2024-05-09T09:38:38.2203354Z 2024/05/09 09:23:23.169091 +0000 INFO db/open.go:260 LogtailStats: Compact[0|0]
2024-05-09T09:38:38.2204823Z 2024/05/09 09:23:23.177410 +0000 INFO dbutils/mem.go:133 HeapInfo:TotalAlloc:11803MB Sys:205MB HeapAlloc:73MB HeapSys:188MB HeapIdle:110MB HeapReleased:110MB HeapInuse:78MB NextGC:147MB NumGC:251 PauseNs:362567235
2024-05-09T09:38:38.2206447Z 2024/05/09 09:23:23.177614 +0000 INFO checkpoint/runner.go:930 [flushtabletail] scan result: pressure 3.4365803003311157e-07, totalsize 369B
2024-05-09T09:38:38.2207931Z 2024/05/09 09:23:23.179436 +0000 INFO dbutils/runtime.go:113 VectorPool[trasient-vector-pool][0/512]: FixSizedVec[0/307] VarlenVec[0/205], Reset/Hit/totalStats:[0/(0,0)0/0]
2024-05-09T09:38:38.2209245Z VectorPool[small-vector-pool][0/10240]: FixSizedVec[0/6144] VarlenVec[0/4096], Reset/Hit/totalStats:[0/(14,1)15/15]
2024-05-09T09:38:38.2210084Z 2024/05/09 09:23:23.179489 +0000 INFO gc/diskcleaner.go:55 JobFactory is start
2024-05-09T09:38:38.2210771Z 2024/05/09 09:23:23.179550 +0000 INFO db/open.go:260 LogtailStats: Compact[0|0]
2024-05-09T09:38:38.2212022Z 2024/05/09 09:23:23.188197 +0000 INFO dbutils/mem.go:133 HeapInfo:TotalAlloc:11803MB Sys:205MB HeapAlloc:73MB HeapSys:188MB HeapIdle:110MB HeapReleased:110MB HeapInuse:78MB NextGC:147MB NumGC:251 PauseNs:362567235
2024-05-09T09:38:38.2213624Z 2024/05/09 09:23:23.188614 +0000 INFO checkpoint/runner.go:930 [flushtabletail] scan result: pressure 3.4365803003311157e-07, totalsize 369B
2024-05-09T09:38:38.2215506Z 2024/05/09 09:23:23.188853 +0000 INFO jobs/flushTableTail.go:244 [Start] {"operation": "[1363]FT-1000-2024-05-09 09:23:23.127329182 +0000 UTC m=+63.022860057", "operand": {"endTs": "1715246603188226524-0", "a-objs": "2551d23701eb,", "delete-obj-ndv": 0}, "operand": 1}
2024-05-09T09:38:38.2216942Z 2024/05/09 09:23:23.189108 +0000 INFO jobs/flushTableTail.go:415 flushtabletail sort obj on mock_2
2024-05-09T09:38:38.2218296Z 2024/05/09 09:23:23.190150 +0000 INFO dbutils/runtime.go:113 VectorPool[trasient-vector-pool][9/512]: FixSizedVec[9/307] VarlenVec[0/205], Reset/Hit/totalStats:[0/(10,0)10/10]
2024-05-09T09:38:38.2219638Z VectorPool[small-vector-pool][0/10240]: FixSizedVec[0/6144] VarlenVec[0/4096], Reset/Hit/totalStats:[0/(14,1)15/15]
2024-05-09T09:38:38.2220477Z 2024/05/09 09:23:23.190244 +0000 INFO gc/diskcleaner.go:55 JobFactory is start
2024-05-09T09:38:38.2221160Z 2024/05/09 09:23:23.190399 +0000 INFO db/open.go:260 LogtailStats: Compact[0|0]
2024-05-09T09:38:38.2223408Z 2024/05/09 09:23:23.193016 +0000 INFO jobs/flushTableTail.go:356 [End] {"operation": "[1363]FT-1000-2024-05-09 09:23:23.127329182 +0000 UTC m=+63.022860057", "txn-start-ts": "1715246603188456924-0", "aobj-deletes": 0, "aobj-merge-rows": 7, "nobj-deletes": 0, "duration": "4.08343ms", "operand": {"endTs": "1715246603188226524-0", "a-objs": "2551d23701eb,", "delete-obj-ndv": 0, "to-objs": "ce8353b410a6,"}}
2024-05-09T09:38:38.2225080Z     tables_test.go:693: 
2024-05-09T09:38:38.2225901Z         	Error Trace:	/home/runner/work/matrixone/matrixone/pkg/vm/engine/tae/db/test/tables_test.go:693
2024-05-09T09:38:38.2226636Z         	Error:      	Should be false
2024-05-09T09:38:38.2227092Z         	Test:       	TestCompaction2
2024-05-09T09:38:38.2227715Z 2024/05/09 09:23:23.194880 +0000 INFO gc/manager.go:152 gc-loop is going to exit
2024-05-09T09:38:38.2228981Z 2024/05/09 09:23:23.198040 +0000 INFO dbutils/mem.go:133 HeapInfo:TotalAlloc:11804MB Sys:205MB HeapAlloc:74MB HeapSys:188MB HeapIdle:109MB HeapReleased:109MB HeapInuse:78MB NextGC:147MB NumGC:251 PauseNs:362567235
2024-05-09T09:38:38.2230614Z 2024/05/09 09:23:23.198286 +0000 INFO checkpoint/runner.go:390 Checkpoint-Start {"entry": "CKP[I][0][ckp 0, truncate 0](0-0->1715246603137793489-0)"}
2024-05-09T09:38:38.2232644Z 2024/05/09 09:23:23.199935 +0000 INFO logtail/storage_usage.go:962 storage usage [I] {"cache mem used": 0.0002900115234375, "applied deletes": "", "storage usage summary when ckp": "\nCKP[I]\t2024-05-09 09:23:23.199910528 +0000 UTC\naccumulated size in this ckp:            0.000000mb, "}
2024-05-09T09:38:38.2234247Z 2024/05/09 09:23:23.200596 +0000 INFO db/scanner.go:54 DBScanner Stopped
2024-05-09T09:38:38.2236836Z 2024/05/09 09:23:23.241189 +0000 INFO checkpoint/runner.go:416 Checkpoint-End {"DBInsertIDX-Size": 176, "DBInsertIDX-Row": 1, "TBLInsertIDX-Size": 424, "TBLInsertIDX-Row": 1, "TBLColInsertIDX-Size": 2992, "TBLColInsertIDX-Row": 5, "TNObjectInfoIDX-Size": 1296, "TNObjectInfoIDX-Row": 4, "totalSize": 4888, "totalRow": 11, "cost": "42.918288ms", "truncate": 1, "lsn": 1, "reserve": 0, "entry": "CKP[I][2][ckp 1, truncate 1](0-0->1715246603137793489-0)"}
2024-05-09T09:38:38.2239354Z 2024/05/09 09:23:23.241413 +0000 INFO checkpoint/runner.go:591 Checkpoint-Start {"entry": "CKP[G][1][ckp 1, truncate 1](0-0->1715246603137793489-1)"}
2024-05-09T09:38:38.2241590Z 2024/05/09 09:23:23.243081 +0000 INFO logtail/storage_usage.go:962 storage usage [G] {"update old data": "", "tables back to track": 0, "accounts cleaned": "", "storage usage summary when ckp": "\nCKP[G]\t2024-05-09 09:23:23.243062231 +0000 UTC\naccumulated size in this ckp:            0.000000mb, "}
2024-05-09T09:38:38.2244860Z 2024/05/09 09:23:23.286530 +0000 INFO checkpoint/runner.go:608 Checkpoint-End {"DBInsertIDX-Size": 176, "DBInsertIDX-Row": 1, "TBLInsertIDX-Size": 424, "TBLInsertIDX-Row": 1, "TBLColInsertIDX-Size": 2992, "TBLColInsertIDX-Row": 5, "TNObjectInfoIDX-Size": 1296, "TNObjectInfoIDX-Row": 4, "totalSize": 4888, "totalRow": 11, "cost": "45.148657ms", "entry": "CKP[G][2][ckp 1, truncate 1](0-0->1715246603137793489-1)"}
2024-05-09T09:38:38.2246767Z 2024/05/09 09:23:23.287087 +0000 INFO db/scheduler.go:81 TaskScheduler Stopped
2024-05-09T09:38:38.2247461Z 2024/05/09 09:23:23.287225 +0000 INFO txnbase/txnmgr.go:624 [Stop] {"txnmgr": {}}
2024-05-09T09:38:38.2248042Z --- FAIL: TestCompaction2 (0.17s)

Expected Behavior

No response

Steps to Reproduce

run ut

Additional information

No response

[jiangxinmeng1]

还没进展

[daviszhen]

https://github.com/matrixorigin/matrixone/actions/runs/9481880757/job/26160163110?pr=16798

[sukki37]

track by #16880