[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:18:14.571484 30943 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.30.55.254:40463
I20260812 06:18:14.572638 30943 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:18:14.573310 30943 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:14.581073 30949 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:14.581084 30943 server_base.cc:1061] running on GCE node
W20260812 06:18:14.581102 30950 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:14.581110 30952 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:14.582059 30943 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:14.582264 30943 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:14.582306 30943 hybrid_clock.cc:648] HybridClock initialized: now 1786515494582297 us; error 0 us; skew 500 ppm
I20260812 06:18:14.584669 30943 webserver.cc:533] Webserver started at http://127.30.55.254:35015/ using document root <none> and password file <none>
I20260812 06:18:14.585368 30943 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:14.585446 30943 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:14.585726 30943 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:14.587682 30943 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/master-0-root/instance:
uuid: "ac032cb1172744f0959a7311c5714f33"
format_stamp: "Formatted at 2026-08-12 06:18:14 on dist-test-slave-csg5"
I20260812 06:18:14.591892 30943 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.000s	sys 0.004s
I20260812 06:18:14.594424 30957 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:14.595752 30943 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.001s
I20260812 06:18:14.595906 30943 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/master-0-root
uuid: "ac032cb1172744f0959a7311c5714f33"
format_stamp: "Formatted at 2026-08-12 06:18:14 on dist-test-slave-csg5"
I20260812 06:18:14.596040 30943 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:14.635449 30943 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:14.636277 30943 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:18:14.636483 30943 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:14.644832 30943 rpc_server.cc:307] RPC server started. Bound to: 127.30.55.254:40463
I20260812 06:18:14.644837 31020 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.55.254:40463 every 8 connection(s)
I20260812 06:18:14.647480 31021 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:14.653926 31021 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ac032cb1172744f0959a7311c5714f33: Bootstrap starting.
I20260812 06:18:14.656713 31021 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P ac032cb1172744f0959a7311c5714f33: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:14.657794 31021 log.cc:826] T 00000000000000000000000000000000 P ac032cb1172744f0959a7311c5714f33: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:14.659938 31021 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ac032cb1172744f0959a7311c5714f33: No bootstrap required, opened a new log
I20260812 06:18:14.663149 31021 raft_consensus.cc:359] T 00000000000000000000000000000000 P ac032cb1172744f0959a7311c5714f33 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ac032cb1172744f0959a7311c5714f33" member_type: VOTER }
I20260812 06:18:14.663395 31021 raft_consensus.cc:385] T 00000000000000000000000000000000 P ac032cb1172744f0959a7311c5714f33 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:14.663496 31021 raft_consensus.cc:740] T 00000000000000000000000000000000 P ac032cb1172744f0959a7311c5714f33 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ac032cb1172744f0959a7311c5714f33, State: Initialized, Role: FOLLOWER
I20260812 06:18:14.664140 31021 consensus_queue.cc:260] T 00000000000000000000000000000000 P ac032cb1172744f0959a7311c5714f33 [NON_LEADER]: Queue going to NON_LEADER mode. State: All replicated index: 0, Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0, Current term: 0, Majority size: -1, State: 0, Mode: NON_LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ac032cb1172744f0959a7311c5714f33" member_type: VOTER }
I20260812 06:18:14.664355 31021 raft_consensus.cc:399] T 00000000000000000000000000000000 P ac032cb1172744f0959a7311c5714f33 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:14.664441 31021 raft_consensus.cc:493] T 00000000000000000000000000000000 P ac032cb1172744f0959a7311c5714f33 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:14.664598 31021 raft_consensus.cc:3060] T 00000000000000000000000000000000 P ac032cb1172744f0959a7311c5714f33 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:14.665544 31021 raft_consensus.cc:515] T 00000000000000000000000000000000 P ac032cb1172744f0959a7311c5714f33 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ac032cb1172744f0959a7311c5714f33" member_type: VOTER }
I20260812 06:18:14.666047 31021 leader_election.cc:304] T 00000000000000000000000000000000 P ac032cb1172744f0959a7311c5714f33 [CANDIDATE]: Term 1 election: Election decided. Result: candidate won. Election summary: received 1 responses out of 1 voters: 1 yes votes; 0 no votes. yes voters: ac032cb1172744f0959a7311c5714f33; no voters: 
I20260812 06:18:14.666453 31021 leader_election.cc:290] T 00000000000000000000000000000000 P ac032cb1172744f0959a7311c5714f33 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:14.666779 31024 raft_consensus.cc:2804] T 00000000000000000000000000000000 P ac032cb1172744f0959a7311c5714f33 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:14.667081 31024 raft_consensus.cc:697] T 00000000000000000000000000000000 P ac032cb1172744f0959a7311c5714f33 [term 1 LEADER]: Becoming Leader. State: Replica: ac032cb1172744f0959a7311c5714f33, State: Running, Role: LEADER
I20260812 06:18:14.667469 31024 consensus_queue.cc:237] T 00000000000000000000000000000000 P ac032cb1172744f0959a7311c5714f33 [LEADER]: Queue going to LEADER mode. State: All replicated index: 0, Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0, Current term: 1, Majority size: 1, State: 0, Mode: LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ac032cb1172744f0959a7311c5714f33" member_type: VOTER }
I20260812 06:18:14.667685 31021 sys_catalog.cc:565] T 00000000000000000000000000000000 P ac032cb1172744f0959a7311c5714f33 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:14.669541 31027 sys_catalog.cc:455] T 00000000000000000000000000000000 P ac032cb1172744f0959a7311c5714f33 [sys.catalog]: SysCatalogTable state changed. Reason: New leader ac032cb1172744f0959a7311c5714f33. Latest consensus state: current_term: 1 leader_uuid: "ac032cb1172744f0959a7311c5714f33" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ac032cb1172744f0959a7311c5714f33" member_type: VOTER } }
I20260812 06:18:14.669587 31025 sys_catalog.cc:455] T 00000000000000000000000000000000 P ac032cb1172744f0959a7311c5714f33 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "ac032cb1172744f0959a7311c5714f33" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ac032cb1172744f0959a7311c5714f33" member_type: VOTER } }
I20260812 06:18:14.669710 31027 sys_catalog.cc:458] T 00000000000000000000000000000000 P ac032cb1172744f0959a7311c5714f33 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:14.669710 31025 sys_catalog.cc:458] T 00000000000000000000000000000000 P ac032cb1172744f0959a7311c5714f33 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:14.670135 31038 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:14.670321 30943 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:14.673105 31038 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:14.679128 31038 catalog_manager.cc:1383] Generated new cluster ID: c81ff72aaf07409c98090259d83b8fb2
I20260812 06:18:14.679242 31038 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:14.687458 31038 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:14.688778 31038 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:14.701632 31038 catalog_manager.cc:6092] T 00000000000000000000000000000000 P ac032cb1172744f0959a7311c5714f33: Generated new TSK 0
I20260812 06:18:14.702461 31038 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:14.735507 30943 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:14.739676 31047 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:14.739774 31046 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:14.739859 31049 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:14.739949 30943 server_base.cc:1061] running on GCE node
I20260812 06:18:14.740165 30943 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:14.740231 30943 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:14.740255 30943 hybrid_clock.cc:648] HybridClock initialized: now 1786515494740254 us; error 0 us; skew 500 ppm
I20260812 06:18:14.741428 30943 webserver.cc:533] Webserver started at http://127.30.55.193:42479/ using document root <none> and password file <none>
I20260812 06:18:14.741762 30943 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:14.741844 30943 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:14.741933 30943 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:14.742497 30943 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/instance:
uuid: "fcb2c409ec094905b0a2b937462dfa82"
format_stamp: "Formatted at 2026-08-12 06:18:14 on dist-test-slave-csg5"
I20260812 06:18:14.744261 30943 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:14.745424 31054 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:14.745688 30943 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:14.745769 30943 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root
uuid: "fcb2c409ec094905b0a2b937462dfa82"
format_stamp: "Formatted at 2026-08-12 06:18:14 on dist-test-slave-csg5"
I20260812 06:18:14.745867 30943 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:14.787598 30943 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:14.788146 30943 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:14.788712 30943 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:14.789707 30943 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:14.789767 30943 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:14.789855 30943 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:14.789899 30943 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:14.797719 30943 rpc_server.cc:307] RPC server started. Bound to: 127.30.55.193:37629
I20260812 06:18:14.797763 31127 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.55.193:37629 every 8 connection(s)
I20260812 06:18:14.815225 31128 heartbeater.cc:344] Connected to a master server at 127.30.55.254:40463
I20260812 06:18:14.815544 31128 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:14.816044 31128 heartbeater.cc:507] Master 127.30.55.254:40463 requested a full tablet report, sending...
I20260812 06:18:14.817584 30977 ts_manager.cc:194] Registered new tserver with Master: fcb2c409ec094905b0a2b937462dfa82 (127.30.55.193:37629)
I20260812 06:18:14.817804 30943 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.019318577s
I20260812 06:18:14.819223 30977 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:51808
I20260812 06:18:14.829217 30977 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:51820:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:14.844223 31083 tablet_service.cc:1511] Processing CreateTablet for tablet 5eb9133f78e24b46a489971489017159 (DEFAULT_TABLE table=heavy-update-compaction-test [id=c20c662c949b4670abd6d16e7804d4dc]), partition=
I20260812 06:18:14.844798 31083 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 5eb9133f78e24b46a489971489017159. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:14.847481 31143 tablet_bootstrap.cc:492] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Bootstrap starting.
I20260812 06:18:14.848589 31143 tablet_bootstrap.cc:654] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:14.849762 31143 tablet_bootstrap.cc:492] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: No bootstrap required, opened a new log
I20260812 06:18:14.849901 31143 ts_tablet_manager.cc:1403] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:14.850346 31143 raft_consensus.cc:359] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fcb2c409ec094905b0a2b937462dfa82" member_type: VOTER last_known_addr { host: "127.30.55.193" port: 37629 } }
I20260812 06:18:14.850487 31143 raft_consensus.cc:385] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:14.850546 31143 raft_consensus.cc:740] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: fcb2c409ec094905b0a2b937462dfa82, State: Initialized, Role: FOLLOWER
I20260812 06:18:14.850736 31143 consensus_queue.cc:260] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82 [NON_LEADER]: Queue going to NON_LEADER mode. State: All replicated index: 0, Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0, Current term: 0, Majority size: -1, State: 0, Mode: NON_LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fcb2c409ec094905b0a2b937462dfa82" member_type: VOTER last_known_addr { host: "127.30.55.193" port: 37629 } }
I20260812 06:18:14.850831 31143 raft_consensus.cc:399] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:14.850858 31143 raft_consensus.cc:493] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:14.850939 31143 raft_consensus.cc:3060] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:14.851708 31143 raft_consensus.cc:515] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fcb2c409ec094905b0a2b937462dfa82" member_type: VOTER last_known_addr { host: "127.30.55.193" port: 37629 } }
I20260812 06:18:14.851892 31143 leader_election.cc:304] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82 [CANDIDATE]: Term 1 election: Election decided. Result: candidate won. Election summary: received 1 responses out of 1 voters: 1 yes votes; 0 no votes. yes voters: fcb2c409ec094905b0a2b937462dfa82; no voters: 
I20260812 06:18:14.852221 31143 leader_election.cc:290] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:14.852341 31145 raft_consensus.cc:2804] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:14.852588 31145 raft_consensus.cc:697] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82 [term 1 LEADER]: Becoming Leader. State: Replica: fcb2c409ec094905b0a2b937462dfa82, State: Running, Role: LEADER
I20260812 06:18:14.852691 31143 ts_tablet_manager.cc:1434] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:14.852813 31145 consensus_queue.cc:237] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82 [LEADER]: Queue going to LEADER mode. State: All replicated index: 0, Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0, Current term: 1, Majority size: 1, State: 0, Mode: LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fcb2c409ec094905b0a2b937462dfa82" member_type: VOTER last_known_addr { host: "127.30.55.193" port: 37629 } }
I20260812 06:18:14.853174 31128 heartbeater.cc:499] Master 127.30.55.254:40463 was elected leader, sending a full tablet report...
I20260812 06:18:14.855669 30977 catalog_manager.cc:5719] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82 reported cstate change: term changed from 0 to 1, leader changed from <none> to fcb2c409ec094905b0a2b937462dfa82 (127.30.55.193). New cstate: current_term: 1 leader_uuid: "fcb2c409ec094905b0a2b937462dfa82" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fcb2c409ec094905b0a2b937462dfa82" member_type: VOTER last_known_addr { host: "127.30.55.193" port: 37629 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:14.922559 30943 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.057s	user 0.023s	sys 0.003s
I20260812 06:18:15.049033 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushMRSOp(5eb9133f78e24b46a489971489017159): perf score=15.086190
I20260812 06:18:15.231011 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushMRSOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.181s	user 0.140s	sys 0.037s Metrics: {"bytes_written":13086952,"cfile_init":1,"compiler_manager_pool.queue_time_us":265,"delete_count":0,"dirs.queue_time_us":45,"dirs.run_cpu_time_us":229,"dirs.run_wall_time_us":1060,"drs_written":1,"lbm_read_time_us":162,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44552,"lbm_writes_lt_1ms":676,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":132352,"thread_start_us":156,"threads_started":1,"update_count":1595}
I20260812 06:18:15.232549 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=3.181125
I20260812 06:18:15.249254 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.016s	user 0.007s	sys 0.007s Metrics: {"bytes_written":4512907,"delete_count":0,"lbm_write_time_us":6757,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:15.249864 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling LogGCOp(5eb9133f78e24b46a489971489017159): free 8725963 bytes of WAL
I20260812 06:18:15.250172 31059 log_reader.cc:385] T 5eb9133f78e24b46a489971489017159: removed 1 log segments from log reader
I20260812 06:18:15.250248 31059 log.cc:1079] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/5eb9133f78e24b46a489971489017159/wal-000000001 (ops 1-6)
I20260812 06:18:15.253006 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: LogGCOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:15.253592 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=1.196750
I20260812 06:18:15.265617 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":2912930,"delete_count":0,"lbm_write_time_us":4300,"lbm_writes_lt_1ms":74,"reinsert_count":0,"update_count":355}
I20260812 06:18:15.266185 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling UndoDeltaBlockGCOp(5eb9133f78e24b46a489971489017159): 12308956 bytes on disk
I20260812 06:18:15.266870 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: UndoDeltaBlockGCOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":80,"lbm_reads_lt_1ms":4}
I20260812 06:18:15.267326 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling MajorDeltaCompactionOp(5eb9133f78e24b46a489971489017159): perf score=1.000000
I20260812 06:18:15.461876 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: MajorDeltaCompactionOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.194s	user 0.118s	sys 0.063s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733824,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":676,"lbm_read_time_us":11485,"lbm_reads_lt_1ms":569,"lbm_write_time_us":30345,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":331,"threads_started":5,"update_count":2500}
I20260812 06:18:15.462495 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=14.095187
I20260812 06:18:15.519670 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.057s	user 0.046s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23826,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:15.520220 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=2.188937
I20260812 06:18:15.533605 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4275,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.534242 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling MajorDeltaCompactionOp(5eb9133f78e24b46a489971489017159): perf score=1.000000
I20260812 06:18:15.706367 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: MajorDeltaCompactionOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.172s	user 0.134s	sys 0.029s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":201,"lbm_read_time_us":9156,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32753,"lbm_writes_lt_1ms":543,"mutex_wait_us":65,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14208,"update_count":2500}
I20260812 06:18:15.707103 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=11.118625
I20260812 06:18:15.754276 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.047s	user 0.023s	sys 0.020s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":21198,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:15.755025 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=2.188937
I20260812 06:18:15.773097 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.018s	user 0.007s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6563,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:15.773682 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling MajorDeltaCompactionOp(5eb9133f78e24b46a489971489017159): perf score=1.000000
I20260812 06:18:15.910779 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: MajorDeltaCompactionOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.137s	user 0.115s	sys 0.022s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631305,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":297,"lbm_read_time_us":10320,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26702,"lbm_writes_lt_1ms":443,"mutex_wait_us":32,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2000}
I20260812 06:18:15.911727 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=10.126437
I20260812 06:18:15.954205 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.042s	user 0.028s	sys 0.005s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15989,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:15.954852 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=2.188937
I20260812 06:18:15.967893 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4565,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.968472 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling MajorDeltaCompactionOp(5eb9133f78e24b46a489971489017159): perf score=1.000000
I20260812 06:18:16.092118 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: MajorDeltaCompactionOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.123s	user 0.117s	sys 0.006s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":777,"lbm_read_time_us":8396,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23261,"lbm_writes_lt_1ms":443,"mutex_wait_us":283,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14208,"update_count":2000}
I20260812 06:18:16.092681 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=10.126437
I20260812 06:18:16.151183 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.058s	user 0.023s	sys 0.025s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17673,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:16.151778 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=2.188937
I20260812 06:18:16.164551 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4899,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.165109 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling MajorDeltaCompactionOp(5eb9133f78e24b46a489971489017159): perf score=1.000000
I20260812 06:18:16.345397 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: MajorDeltaCompactionOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.180s	user 0.129s	sys 0.051s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":339,"lbm_read_time_us":13639,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28290,"lbm_writes_lt_1ms":443,"mutex_wait_us":32,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":27264,"update_count":2000}
I20260812 06:18:16.346129 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=10.126437
I20260812 06:18:16.398032 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.052s	user 0.021s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17828,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:16.398756 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=2.188937
I20260812 06:18:16.412895 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.014s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4826,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.413617 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling MajorDeltaCompactionOp(5eb9133f78e24b46a489971489017159): perf score=1.000000
I20260812 06:18:16.556273 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: MajorDeltaCompactionOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.142s	user 0.110s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":570,"lbm_read_time_us":9383,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28880,"lbm_writes_lt_1ms":443,"mutex_wait_us":302,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12800,"update_count":2000}
I20260812 06:18:16.557030 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=10.126437
I20260812 06:18:16.597529 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.040s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17062,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:16.598235 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=2.188937
I20260812 06:18:16.616575 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.018s	user 0.009s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7356,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.617122 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushMRSOp(5eb9133f78e24b46a489971489017159): perf score=1.000000
I20260812 06:18:16.670441 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushMRSOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.053s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":87,"dirs.run_cpu_time_us":249,"dirs.run_wall_time_us":2005,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2037,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:16.671379 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling LogGCOp(5eb9133f78e24b46a489971489017159): free 124257196 bytes of WAL
I20260812 06:18:16.671638 31059 log_reader.cc:385] T 5eb9133f78e24b46a489971489017159: removed 12 log segments from log reader
I20260812 06:18:16.671686 31059 log.cc:1079] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/5eb9133f78e24b46a489971489017159/wal-000000002 (ops 7-11)
I20260812 06:18:16.671720 31059 log.cc:1079] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/5eb9133f78e24b46a489971489017159/wal-000000003 (ops 12-16)
I20260812 06:18:16.671788 31059 log.cc:1079] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/5eb9133f78e24b46a489971489017159/wal-000000004 (ops 17-20)
I20260812 06:18:16.671826 31059 log.cc:1079] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/5eb9133f78e24b46a489971489017159/wal-000000005 (ops 21-25)
I20260812 06:18:16.671870 31059 log.cc:1079] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/5eb9133f78e24b46a489971489017159/wal-000000006 (ops 26-30)
I20260812 06:18:16.671890 31059 log.cc:1079] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/5eb9133f78e24b46a489971489017159/wal-000000007 (ops 31-35)
I20260812 06:18:16.671947 31059 log.cc:1079] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/5eb9133f78e24b46a489971489017159/wal-000000008 (ops 36-40)
I20260812 06:18:16.671988 31059 log.cc:1079] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/5eb9133f78e24b46a489971489017159/wal-000000009 (ops 41-45)
I20260812 06:18:16.672030 31059 log.cc:1079] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/5eb9133f78e24b46a489971489017159/wal-000000010 (ops 46-50)
I20260812 06:18:16.672070 31059 log.cc:1079] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/5eb9133f78e24b46a489971489017159/wal-000000011 (ops 51-55)
I20260812 06:18:16.672108 31059 log.cc:1079] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/5eb9133f78e24b46a489971489017159/wal-000000012 (ops 56-60)
I20260812 06:18:16.672149 31059 log.cc:1079] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/5eb9133f78e24b46a489971489017159/wal-000000013 (ops 61-65)
I20260812 06:18:16.702869 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: LogGCOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.031s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:18:16.703363 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=7.149875
I20260812 06:18:16.729707 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.026s	user 0.014s	sys 0.009s Metrics: {"bytes_written":8615324,"delete_count":0,"lbm_write_time_us":10926,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:18:16.730490 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling LogGCOp(5eb9133f78e24b46a489971489017159): free 8767174 bytes of WAL
I20260812 06:18:16.730804 31059 log_reader.cc:385] T 5eb9133f78e24b46a489971489017159: removed 1 log segments from log reader
I20260812 06:18:16.730856 31059 log.cc:1079] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/5eb9133f78e24b46a489971489017159/wal-000000014 (ops 66-70)
I20260812 06:18:16.732770 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: LogGCOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:16.733183 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=2.188937
I20260812 06:18:16.747088 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.014s	user 0.010s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4482,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:16.747848 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling MajorDeltaCompactionOp(5eb9133f78e24b46a489971489017159): perf score=1.000000
I20260812 06:18:16.959478 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: MajorDeltaCompactionOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.211s	user 0.166s	sys 0.045s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938779,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1171,"lbm_read_time_us":13346,"lbm_reads_lt_1ms":766,"lbm_write_time_us":43255,"lbm_writes_lt_1ms":743,"mutex_wait_us":283,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":5120,"thread_start_us":100,"threads_started":1,"update_count":3500}
I20260812 06:18:16.960199 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling UndoDeltaBlockGCOp(5eb9133f78e24b46a489971489017159): 481 bytes on disk
I20260812 06:18:16.961252 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: UndoDeltaBlockGCOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":111,"lbm_reads_lt_1ms":4}
I20260812 06:18:16.962991 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=14.095187
W20260812 06:18:17.030186 31148 log.cc:927] Time spent T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Append to log took a long time: real 0.057s	user 0.000s	sys 0.005s
I20260812 06:18:17.036497 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.073s	user 0.020s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20162,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:17.037078 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling MajorDeltaCompactionOp(5eb9133f78e24b46a489971489017159): perf score=1.000000
I20260812 06:18:17.173844 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: MajorDeltaCompactionOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.137s	user 0.116s	sys 0.017s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631192,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":720,"lbm_read_time_us":7946,"lbm_reads_lt_1ms":463,"lbm_write_time_us":26529,"lbm_writes_lt_1ms":443,"mutex_wait_us":479,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2000}
I20260812 06:18:17.174804 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=10.126437
I20260812 06:18:17.218952 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.043s	user 0.017s	sys 0.025s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18869,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:17.219615 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=2.188937
I20260812 06:18:17.231024 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4335,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.231565 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling MajorDeltaCompactionOp(5eb9133f78e24b46a489971489017159): perf score=1.000000
I20260812 06:18:17.374816 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: MajorDeltaCompactionOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.143s	user 0.108s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":324,"lbm_read_time_us":8375,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27374,"lbm_writes_lt_1ms":443,"mutex_wait_us":56,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2000}
I20260812 06:18:17.375567 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=10.126437
I20260812 06:18:17.420130 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.044s	user 0.030s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19010,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:17.420830 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling MajorDeltaCompactionOp(5eb9133f78e24b46a489971489017159): perf score=1.000000
I20260812 06:18:17.529107 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: MajorDeltaCompactionOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.108s	user 0.083s	sys 0.024s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":404,"lbm_read_time_us":5988,"lbm_reads_lt_1ms":363,"lbm_write_time_us":20884,"lbm_writes_lt_1ms":343,"mutex_wait_us":66,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":1500}
I20260812 06:18:17.530114 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=10.126437
I20260812 06:18:17.579011 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.049s	user 0.031s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18651,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:17.579689 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=2.188937
I20260812 06:18:17.593029 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4547,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.593770 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling MajorDeltaCompactionOp(5eb9133f78e24b46a489971489017159): perf score=1.000000
I20260812 06:18:17.750483 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: MajorDeltaCompactionOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.156s	user 0.130s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":351,"lbm_read_time_us":10154,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27561,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":36864,"update_count":2000}
I20260812 06:18:17.751194 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=10.126437
I20260812 06:18:17.800328 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.049s	user 0.023s	sys 0.015s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16878,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:17.800983 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=2.188937
I20260812 06:18:17.815312 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.014s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4810,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.816074 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling MajorDeltaCompactionOp(5eb9133f78e24b46a489971489017159): perf score=1.000000
I20260812 06:18:17.955864 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: MajorDeltaCompactionOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.140s	user 0.107s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":641,"lbm_read_time_us":8520,"lbm_reads_lt_1ms":468,"lbm_write_time_us":28781,"lbm_writes_lt_1ms":443,"mutex_wait_us":290,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":44544,"update_count":2000}
I20260812 06:18:17.956646 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=10.126437
I20260812 06:18:18.009513 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.053s	user 0.028s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18515,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:18.010109 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=2.188937
I20260812 06:18:18.023281 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.013s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4613,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.024149 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling MajorDeltaCompactionOp(5eb9133f78e24b46a489971489017159): perf score=1.000000
I20260812 06:18:18.157399 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: MajorDeltaCompactionOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.133s	user 0.112s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":831,"lbm_read_time_us":8422,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26183,"lbm_writes_lt_1ms":443,"mutex_wait_us":306,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2000}
I20260812 06:18:18.158383 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=11.118625
I20260812 06:18:18.207840 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.049s	user 0.029s	sys 0.019s Metrics: {"bytes_written":12512610,"delete_count":0,"lbm_write_time_us":18698,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":306,"reinsert_count":0,"update_count":1525}
I20260812 06:18:18.208880 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=2.188937
I20260812 06:18:18.220994 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3897534,"delete_count":0,"lbm_write_time_us":4440,"lbm_writes_lt_1ms":98,"reinsert_count":0,"update_count":475}
I20260812 06:18:18.221693 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushMRSOp(5eb9133f78e24b46a489971489017159): perf score=1.000000
I20260812 06:18:18.259056 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushMRSOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.037s	user 0.029s	sys 0.005s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":99,"dirs.run_cpu_time_us":218,"dirs.run_wall_time_us":1595,"drs_written":1,"lbm_read_time_us":95,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1768,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:18.260007 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling LogGCOp(5eb9133f78e24b46a489971489017159): free 124257193 bytes of WAL
I20260812 06:18:18.260321 31059 log_reader.cc:385] T 5eb9133f78e24b46a489971489017159: removed 12 log segments from log reader
I20260812 06:18:18.260396 31059 log.cc:1079] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/5eb9133f78e24b46a489971489017159/wal-000000015 (ops 71-75)
I20260812 06:18:18.260442 31059 log.cc:1079] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/5eb9133f78e24b46a489971489017159/wal-000000016 (ops 76-80)
I20260812 06:18:18.260465 31059 log.cc:1079] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/5eb9133f78e24b46a489971489017159/wal-000000017 (ops 81-84)
I20260812 06:18:18.260489 31059 log.cc:1079] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/5eb9133f78e24b46a489971489017159/wal-000000018 (ops 85-89)
I20260812 06:18:18.260526 31059 log.cc:1079] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/5eb9133f78e24b46a489971489017159/wal-000000019 (ops 90-94)
I20260812 06:18:18.260563 31059 log.cc:1079] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/5eb9133f78e24b46a489971489017159/wal-000000020 (ops 95-99)
I20260812 06:18:18.260596 31059 log.cc:1079] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/5eb9133f78e24b46a489971489017159/wal-000000021 (ops 100-104)
I20260812 06:18:18.260627 31059 log.cc:1079] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/5eb9133f78e24b46a489971489017159/wal-000000022 (ops 105-109)
I20260812 06:18:18.260656 31059 log.cc:1079] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/5eb9133f78e24b46a489971489017159/wal-000000023 (ops 110-114)
I20260812 06:18:18.260701 31059 log.cc:1079] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/5eb9133f78e24b46a489971489017159/wal-000000024 (ops 115-119)
I20260812 06:18:18.260741 31059 log.cc:1079] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/5eb9133f78e24b46a489971489017159/wal-000000025 (ops 120-124)
I20260812 06:18:18.260767 31059 log.cc:1079] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/5eb9133f78e24b46a489971489017159/wal-000000026 (ops 125-129)
I20260812 06:18:18.292688 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: LogGCOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.032s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:18:18.293334 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=2.188937
I20260812 06:18:18.317878 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.024s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6682,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.318459 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling UndoDeltaBlockGCOp(5eb9133f78e24b46a489971489017159): 461 bytes on disk
I20260812 06:18:18.319060 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: UndoDeltaBlockGCOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4}
I20260812 06:18:18.319903 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=2.188937
I20260812 06:18:18.336469 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6043,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.337355 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling MajorDeltaCompactionOp(5eb9133f78e24b46a489971489017159): perf score=1.000000
I20260812 06:18:18.539721 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: MajorDeltaCompactionOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.202s	user 0.148s	sys 0.048s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836368,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":513,"lbm_read_time_us":13356,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33798,"lbm_writes_lt_1ms":643,"mutex_wait_us":57,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":110848,"thread_start_us":89,"threads_started":1,"update_count":3000}
I20260812 06:18:18.540530 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=14.095187
I20260812 06:18:18.602330 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.062s	user 0.037s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26658,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:18.602974 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling MajorDeltaCompactionOp(5eb9133f78e24b46a489971489017159): perf score=1.000000
I20260812 06:18:18.755105 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: MajorDeltaCompactionOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.152s	user 0.123s	sys 0.028s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631193,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":956,"lbm_read_time_us":10579,"lbm_reads_lt_1ms":463,"lbm_write_time_us":27724,"lbm_writes_lt_1ms":443,"mutex_wait_us":426,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:18.756311 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=10.126437
I20260812 06:18:18.794799 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.038s	user 0.017s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16665,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:18.795497 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=2.188937
I20260812 06:18:18.816408 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.021s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5557,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.817241 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling MajorDeltaCompactionOp(5eb9133f78e24b46a489971489017159): perf score=1.000000
I20260812 06:18:18.977221 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: MajorDeltaCompactionOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.160s	user 0.114s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1055,"lbm_read_time_us":10245,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26439,"lbm_writes_lt_1ms":443,"mutex_wait_us":303,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10240,"update_count":2000}
I20260812 06:18:18.978156 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=10.126437
I20260812 06:18:19.047199 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.069s	user 0.037s	sys 0.010s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":20567,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:19.048077 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=2.188937
I20260812 06:18:19.070598 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.022s	user 0.015s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":8030,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.071345 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling MajorDeltaCompactionOp(5eb9133f78e24b46a489971489017159): perf score=1.000000
I20260812 06:18:19.242210 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: MajorDeltaCompactionOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.171s	user 0.129s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1199,"lbm_read_time_us":15440,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28921,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:18:19.243458 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=11.118625
I20260812 06:18:19.315133 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.071s	user 0.037s	sys 0.022s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":25395,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:19.315898 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=6.157687
I20260812 06:18:19.362450 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.046s	user 0.025s	sys 0.008s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":14745,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:18:19.363336 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=2.188937
I20260812 06:18:19.383507 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.020s	user 0.014s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6987,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.384260 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling MajorDeltaCompactionOp(5eb9133f78e24b46a489971489017159): perf score=1.000000
I20260812 06:18:19.578980 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: MajorDeltaCompactionOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.194s	user 0.151s	sys 0.036s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836259,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":342,"lbm_read_time_us":11871,"lbm_reads_lt_1ms":673,"lbm_write_time_us":40638,"lbm_writes_lt_1ms":643,"mutex_wait_us":81,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":17536,"update_count":3000}
I20260812 06:18:19.579855 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=14.095187
I20260812 06:18:19.643699 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.064s	user 0.039s	sys 0.019s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":28935,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:19.644450 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=2.188937
I20260812 06:18:19.667377 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.023s	user 0.015s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7693,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.668004 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling MajorDeltaCompactionOp(5eb9133f78e24b46a489971489017159): perf score=1.000000
I20260812 06:18:19.897228 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: MajorDeltaCompactionOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.229s	user 0.191s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1554,"lbm_read_time_us":17483,"lbm_reads_lt_1ms":564,"lbm_write_time_us":41618,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:19.897918 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=19.056125
I20260812 06:18:19.963876 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.066s	user 0.046s	sys 0.016s Metrics: {"bytes_written":20922558,"delete_count":0,"lbm_write_time_us":29856,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":511,"reinsert_count":0,"update_count":2550}
I20260812 06:18:19.964516 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=6.157687
I20260812 06:18:19.989490 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.025s	user 0.009s	sys 0.012s Metrics: {"bytes_written":7794837,"delete_count":0,"lbm_write_time_us":10074,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:18:19.990092 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushMRSOp(5eb9133f78e24b46a489971489017159): perf score=1.000000
I20260812 06:18:20.046006 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushMRSOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.056s	user 0.031s	sys 0.004s Metrics: {"bytes_written":1357582,"cfile_init":1,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":279,"dirs.run_wall_time_us":1878,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2724,"lbm_writes_lt_1ms":44,"peak_mem_usage":0,"rows_written":33}
I20260812 06:18:20.046983 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling LogGCOp(5eb9133f78e24b46a489971489017159): free 132571650 bytes of WAL
I20260812 06:18:20.047309 31059 log_reader.cc:385] T 5eb9133f78e24b46a489971489017159: removed 13 log segments from log reader
I20260812 06:18:20.047358 31059 log.cc:1079] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/5eb9133f78e24b46a489971489017159/wal-000000027 (ops 130-134)
I20260812 06:18:20.047386 31059 log.cc:1079] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/5eb9133f78e24b46a489971489017159/wal-000000028 (ops 135-139)
I20260812 06:18:20.047441 31059 log.cc:1079] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/5eb9133f78e24b46a489971489017159/wal-000000029 (ops 140-144)
I20260812 06:18:20.047484 31059 log.cc:1079] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/5eb9133f78e24b46a489971489017159/wal-000000030 (ops 145-149)
I20260812 06:18:20.047502 31059 log.cc:1079] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/5eb9133f78e24b46a489971489017159/wal-000000031 (ops 150-154)
I20260812 06:18:20.047549 31059 log.cc:1079] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/5eb9133f78e24b46a489971489017159/wal-000000032 (ops 155-158)
I20260812 06:18:20.047601 31059 log.cc:1079] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/5eb9133f78e24b46a489971489017159/wal-000000033 (ops 159-163)
I20260812 06:18:20.047657 31059 log.cc:1079] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/5eb9133f78e24b46a489971489017159/wal-000000034 (ops 164-168)
I20260812 06:18:20.047705 31059 log.cc:1079] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/5eb9133f78e24b46a489971489017159/wal-000000035 (ops 169-173)
I20260812 06:18:20.047745 31059 log.cc:1079] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/5eb9133f78e24b46a489971489017159/wal-000000036 (ops 174-178)
I20260812 06:18:20.047783 31059 log.cc:1079] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/5eb9133f78e24b46a489971489017159/wal-000000037 (ops 179-183)
I20260812 06:18:20.047821 31059 log.cc:1079] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/5eb9133f78e24b46a489971489017159/wal-000000038 (ops 184-188)
I20260812 06:18:20.047856 31059 log.cc:1079] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/5eb9133f78e24b46a489971489017159/wal-000000039 (ops 189-192)
I20260812 06:18:20.076468 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: LogGCOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.029s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:18:20.076956 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=6.157687
I20260812 06:18:20.106946 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.030s	user 0.022s	sys 0.008s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":13077,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:20.107529 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling UndoDeltaBlockGCOp(5eb9133f78e24b46a489971489017159): 508 bytes on disk
I20260812 06:18:20.107995 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: UndoDeltaBlockGCOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:18:20.108565 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159): perf score=2.188937
I20260812 06:18:20.122011 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: FlushDeltaMemStoresOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4734,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:20.122628 31129 maintenance_manager.cc:419] P fcb2c409ec094905b0a2b937462dfa82: Scheduling MajorDeltaCompactionOp(5eb9133f78e24b46a489971489017159): perf score=1.000000
I20260812 06:18:20.198109 30943 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.275s	user 1.951s	sys 0.113s
I20260812 06:18:20.348376 30943 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.150s	user 0.002s	sys 0.000s
I20260812 06:18:20.349362 30943 tablet_server.cc:179] TabletServer@127.30.55.193:0 shutting down...
I20260812 06:18:20.387816 31059 maintenance_manager.cc:643] P fcb2c409ec094905b0a2b937462dfa82: MajorDeltaCompactionOp(5eb9133f78e24b46a489971489017159) complete. Timing: real 0.265s	user 0.164s	sys 0.101s Metrics: {"cfile_cache_miss":1034,"cfile_cache_miss_bytes":45246026,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":819,"lbm_read_time_us":19181,"lbm_reads_lt_1ms":1070,"lbm_write_time_us":51619,"lbm_writes_lt_1ms":1043,"mutex_wait_us":108,"peak_mem_usage":125248760,"reinsert_count":0,"spinlock_wait_cycles":9088,"thread_start_us":88,"threads_started":1,"update_count":5000}
I20260812 06:18:20.388741 30943 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:20.389351 30943 tablet_replica.cc:333] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82: stopping tablet replica
I20260812 06:18:20.389617 30943 raft_consensus.cc:2243] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:20.389942 30943 raft_consensus.cc:2272] T 5eb9133f78e24b46a489971489017159 P fcb2c409ec094905b0a2b937462dfa82 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:20.409909 30943 tablet_server.cc:196] TabletServer@127.30.55.193:0 shutdown complete.
I20260812 06:18:20.495141 30943 master.cc:562] Master@127.30.55.254:40463 shutting down...
I20260812 06:18:20.499545 30943 raft_consensus.cc:2243] T 00000000000000000000000000000000 P ac032cb1172744f0959a7311c5714f33 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:20.499728 30943 raft_consensus.cc:2272] T 00000000000000000000000000000000 P ac032cb1172744f0959a7311c5714f33 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:20.499778 30943 tablet_replica.cc:333] T 00000000000000000000000000000000 P ac032cb1172744f0959a7311c5714f33: stopping tablet replica
I20260812 06:18:20.514461 30943 master.cc:584] Master@127.30.55.254:40463 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (6036 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:20.607579 30943 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.30.55.254:34451
I20260812 06:18:20.607976 30943 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:20.610577 31163 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:20.610581 30943 server_base.cc:1061] running on GCE node
W20260812 06:18:20.610818 31165 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:20.610637 31162 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:20.611110 30943 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:20.611155 30943 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:20.611171 30943 hybrid_clock.cc:648] HybridClock initialized: now 1786515500611171 us; error 0 us; skew 500 ppm
I20260812 06:18:20.612039 30943 webserver.cc:533] Webserver started at http://127.30.55.254:39773/ using document root <none> and password file <none>
I20260812 06:18:20.612182 30943 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:20.612224 30943 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:20.612278 30943 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:20.612653 30943 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/master-0-root/instance:
uuid: "98c0bb8d751647d5bc5d20649e4b31ce"
format_stamp: "Formatted at 2026-08-12 06:18:20 on dist-test-slave-csg5"
I20260812 06:18:20.614485 30943 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:18:20.615741 31170 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:20.616086 30943 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:20.616250 30943 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/master-0-root
uuid: "98c0bb8d751647d5bc5d20649e4b31ce"
format_stamp: "Formatted at 2026-08-12 06:18:20 on dist-test-slave-csg5"
I20260812 06:18:20.616325 30943 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:20.663775 30943 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:20.664224 30943 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:20.668953 30943 rpc_server.cc:307] RPC server started. Bound to: 127.30.55.254:34451
I20260812 06:18:20.670575 31224 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.55.254:34451 every 8 connection(s)
I20260812 06:18:20.672726 31225 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:20.683833 31225 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 98c0bb8d751647d5bc5d20649e4b31ce: Bootstrap starting.
I20260812 06:18:20.694211 31225 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 98c0bb8d751647d5bc5d20649e4b31ce: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:20.695734 31225 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 98c0bb8d751647d5bc5d20649e4b31ce: No bootstrap required, opened a new log
I20260812 06:18:20.696266 31225 raft_consensus.cc:359] T 00000000000000000000000000000000 P 98c0bb8d751647d5bc5d20649e4b31ce [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "98c0bb8d751647d5bc5d20649e4b31ce" member_type: VOTER }
I20260812 06:18:20.696377 31225 raft_consensus.cc:385] T 00000000000000000000000000000000 P 98c0bb8d751647d5bc5d20649e4b31ce [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:20.696399 31225 raft_consensus.cc:740] T 00000000000000000000000000000000 P 98c0bb8d751647d5bc5d20649e4b31ce [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 98c0bb8d751647d5bc5d20649e4b31ce, State: Initialized, Role: FOLLOWER
I20260812 06:18:20.696564 31225 consensus_queue.cc:260] T 00000000000000000000000000000000 P 98c0bb8d751647d5bc5d20649e4b31ce [NON_LEADER]: Queue going to NON_LEADER mode. State: All replicated index: 0, Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0, Current term: 0, Majority size: -1, State: 0, Mode: NON_LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "98c0bb8d751647d5bc5d20649e4b31ce" member_type: VOTER }
I20260812 06:18:20.696661 31225 raft_consensus.cc:399] T 00000000000000000000000000000000 P 98c0bb8d751647d5bc5d20649e4b31ce [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:20.696686 31225 raft_consensus.cc:493] T 00000000000000000000000000000000 P 98c0bb8d751647d5bc5d20649e4b31ce [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:20.696717 31225 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 98c0bb8d751647d5bc5d20649e4b31ce [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:20.697515 31225 raft_consensus.cc:515] T 00000000000000000000000000000000 P 98c0bb8d751647d5bc5d20649e4b31ce [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "98c0bb8d751647d5bc5d20649e4b31ce" member_type: VOTER }
I20260812 06:18:20.697644 31225 leader_election.cc:304] T 00000000000000000000000000000000 P 98c0bb8d751647d5bc5d20649e4b31ce [CANDIDATE]: Term 1 election: Election decided. Result: candidate won. Election summary: received 1 responses out of 1 voters: 1 yes votes; 0 no votes. yes voters: 98c0bb8d751647d5bc5d20649e4b31ce; no voters: 
I20260812 06:18:20.697850 31225 leader_election.cc:290] T 00000000000000000000000000000000 P 98c0bb8d751647d5bc5d20649e4b31ce [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:20.698074 31229 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 98c0bb8d751647d5bc5d20649e4b31ce [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:20.698395 31225 sys_catalog.cc:565] T 00000000000000000000000000000000 P 98c0bb8d751647d5bc5d20649e4b31ce [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:20.698397 31229 raft_consensus.cc:697] T 00000000000000000000000000000000 P 98c0bb8d751647d5bc5d20649e4b31ce [term 1 LEADER]: Becoming Leader. State: Replica: 98c0bb8d751647d5bc5d20649e4b31ce, State: Running, Role: LEADER
I20260812 06:18:20.698882 31229 consensus_queue.cc:237] T 00000000000000000000000000000000 P 98c0bb8d751647d5bc5d20649e4b31ce [LEADER]: Queue going to LEADER mode. State: All replicated index: 0, Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0, Current term: 1, Majority size: 1, State: 0, Mode: LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "98c0bb8d751647d5bc5d20649e4b31ce" member_type: VOTER }
I20260812 06:18:20.699940 31231 sys_catalog.cc:455] T 00000000000000000000000000000000 P 98c0bb8d751647d5bc5d20649e4b31ce [sys.catalog]: SysCatalogTable state changed. Reason: New leader 98c0bb8d751647d5bc5d20649e4b31ce. Latest consensus state: current_term: 1 leader_uuid: "98c0bb8d751647d5bc5d20649e4b31ce" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "98c0bb8d751647d5bc5d20649e4b31ce" member_type: VOTER } }
I20260812 06:18:20.699956 31230 sys_catalog.cc:455] T 00000000000000000000000000000000 P 98c0bb8d751647d5bc5d20649e4b31ce [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "98c0bb8d751647d5bc5d20649e4b31ce" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "98c0bb8d751647d5bc5d20649e4b31ce" member_type: VOTER } }
I20260812 06:18:20.700050 31231 sys_catalog.cc:458] T 00000000000000000000000000000000 P 98c0bb8d751647d5bc5d20649e4b31ce [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:20.700065 31230 sys_catalog.cc:458] T 00000000000000000000000000000000 P 98c0bb8d751647d5bc5d20649e4b31ce [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:20.700372 31239 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:20.701114 31239 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:20.701326 30943 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:20.703246 31239 catalog_manager.cc:1383] Generated new cluster ID: cbfb2bf63b5b4730b4eb8489f8db64d0
I20260812 06:18:20.703328 31239 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:20.724316 31239 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:20.725063 31239 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:20.738615 31239 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 98c0bb8d751647d5bc5d20649e4b31ce: Generated new TSK 0
I20260812 06:18:20.738950 31239 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:20.766304 30943 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:20.769294 31253 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:20.769512 31250 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:20.769450 30943 server_base.cc:1061] running on GCE node
W20260812 06:18:20.769405 31251 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:20.769865 30943 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:20.769917 30943 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:20.769935 30943 hybrid_clock.cc:648] HybridClock initialized: now 1786515500769935 us; error 0 us; skew 500 ppm
I20260812 06:18:20.771138 30943 webserver.cc:533] Webserver started at http://127.30.55.193:36341/ using document root <none> and password file <none>
I20260812 06:18:20.771359 30943 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:20.771442 30943 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:20.771565 30943 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:20.772042 30943 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root/instance:
uuid: "dfea94cdbe654610a4d3730a65cdaea3"
format_stamp: "Formatted at 2026-08-12 06:18:20 on dist-test-slave-csg5"
I20260812 06:18:20.774121 30943 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:20.775604 31261 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:20.775969 30943 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:20.776083 30943 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root
uuid: "dfea94cdbe654610a4d3730a65cdaea3"
format_stamp: "Formatted at 2026-08-12 06:18:20 on dist-test-slave-csg5"
I20260812 06:18:20.776207 30943 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:20.782406 30943 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:20.782927 30943 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:20.783284 30943 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:20.783810 30943 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:20.783877 30943 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:20.783948 30943 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:20.784008 30943 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:20.789193 30943 rpc_server.cc:307] RPC server started. Bound to: 127.30.55.193:46807
I20260812 06:18:20.789245 31332 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.30.55.193:46807 every 8 connection(s)
I20260812 06:18:20.801033 31333 heartbeater.cc:344] Connected to a master server at 127.30.55.254:34451
I20260812 06:18:20.801254 31333 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:20.801498 31333 heartbeater.cc:507] Master 127.30.55.254:34451 requested a full tablet report, sending...
I20260812 06:18:20.802402 31188 ts_manager.cc:194] Registered new tserver with Master: dfea94cdbe654610a4d3730a65cdaea3 (127.30.55.193:46807)
I20260812 06:18:20.803320 30943 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013629881s
I20260812 06:18:20.803362 31188 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:50254
I20260812 06:18:20.812824 31188 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:50264:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:20.824155 31292 tablet_service.cc:1511] Processing CreateTablet for tablet c1095c9509404d84bd115a7950873094 (DEFAULT_TABLE table=heavy-update-compaction-test [id=11b229c09d3e4e0db17bb9b9f0c94513]), partition=
I20260812 06:18:20.824573 31292 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet c1095c9509404d84bd115a7950873094. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:20.827105 31345 tablet_bootstrap.cc:492] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Bootstrap starting.
I20260812 06:18:20.828269 31345 tablet_bootstrap.cc:654] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:20.829751 31345 tablet_bootstrap.cc:492] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: No bootstrap required, opened a new log
I20260812 06:18:20.829890 31345 ts_tablet_manager.cc:1403] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:20.830443 31345 raft_consensus.cc:359] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "dfea94cdbe654610a4d3730a65cdaea3" member_type: VOTER last_known_addr { host: "127.30.55.193" port: 46807 } }
I20260812 06:18:20.830554 31345 raft_consensus.cc:385] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:20.830577 31345 raft_consensus.cc:740] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: dfea94cdbe654610a4d3730a65cdaea3, State: Initialized, Role: FOLLOWER
I20260812 06:18:20.830765 31345 consensus_queue.cc:260] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3 [NON_LEADER]: Queue going to NON_LEADER mode. State: All replicated index: 0, Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0, Current term: 0, Majority size: -1, State: 0, Mode: NON_LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "dfea94cdbe654610a4d3730a65cdaea3" member_type: VOTER last_known_addr { host: "127.30.55.193" port: 46807 } }
I20260812 06:18:20.830880 31345 raft_consensus.cc:399] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:20.830909 31345 raft_consensus.cc:493] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:20.830996 31345 raft_consensus.cc:3060] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:20.831889 31345 raft_consensus.cc:515] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "dfea94cdbe654610a4d3730a65cdaea3" member_type: VOTER last_known_addr { host: "127.30.55.193" port: 46807 } }
I20260812 06:18:20.832057 31345 leader_election.cc:304] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3 [CANDIDATE]: Term 1 election: Election decided. Result: candidate won. Election summary: received 1 responses out of 1 voters: 1 yes votes; 0 no votes. yes voters: dfea94cdbe654610a4d3730a65cdaea3; no voters: 
I20260812 06:18:20.832353 31345 leader_election.cc:290] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:20.832505 31347 raft_consensus.cc:2804] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:20.832773 31347 raft_consensus.cc:697] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3 [term 1 LEADER]: Becoming Leader. State: Replica: dfea94cdbe654610a4d3730a65cdaea3, State: Running, Role: LEADER
I20260812 06:18:20.833015 31333 heartbeater.cc:499] Master 127.30.55.254:34451 was elected leader, sending a full tablet report...
I20260812 06:18:20.833058 31347 consensus_queue.cc:237] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3 [LEADER]: Queue going to LEADER mode. State: All replicated index: 0, Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0, Current term: 1, Majority size: 1, State: 0, Mode: LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "dfea94cdbe654610a4d3730a65cdaea3" member_type: VOTER last_known_addr { host: "127.30.55.193" port: 46807 } }
I20260812 06:18:20.832785 31345 ts_tablet_manager.cc:1434] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:20.834643 31188 catalog_manager.cc:5719] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3 reported cstate change: term changed from 0 to 1, leader changed from <none> to dfea94cdbe654610a4d3730a65cdaea3 (127.30.55.193). New cstate: current_term: 1 leader_uuid: "dfea94cdbe654610a4d3730a65cdaea3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "dfea94cdbe654610a4d3730a65cdaea3" member_type: VOTER last_known_addr { host: "127.30.55.193" port: 46807 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:20.897565 30943 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.058s	user 0.020s	sys 0.004s
I20260812 06:18:21.040235 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushMRSOp(c1095c9509404d84bd115a7950873094): perf score=17.070565
I20260812 06:18:21.191062 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushMRSOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.150s	user 0.119s	sys 0.029s Metrics: {"bytes_written":9476828,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":191,"dirs.run_wall_time_us":1351,"drs_written":1,"lbm_read_time_us":109,"lbm_reads_lt_1ms":4,"lbm_write_time_us":36452,"lbm_writes_lt_1ms":688,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":18688,"update_count":1155}
I20260812 06:18:21.191999 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling LogGCOp(c1095c9509404d84bd115a7950873094): free 20743880 bytes of WAL
I20260812 06:18:21.192371 31266 log_reader.cc:385] T c1095c9509404d84bd115a7950873094: removed 2 log segments from log reader
I20260812 06:18:21.192444 31266 log.cc:1079] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/c1095c9509404d84bd115a7950873094/wal-000000001 (ops 1-6)
I20260812 06:18:21.192502 31266 log.cc:1079] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/c1095c9509404d84bd115a7950873094/wal-000000002 (ops 7-11)
I20260812 06:18:21.196946 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: LogGCOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.005s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:21.197506 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=2.188937
I20260812 06:18:21.214262 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.016s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3241134,"delete_count":0,"lbm_write_time_us":3260,"lbm_writes_lt_1ms":82,"reinsert_count":0,"update_count":395}
I20260812 06:18:21.214814 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling UndoDeltaBlockGCOp(c1095c9509404d84bd115a7950873094): 16411396 bytes on disk
I20260812 06:18:21.215385 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: UndoDeltaBlockGCOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":88,"lbm_reads_lt_1ms":4}
I20260812 06:18:21.215818 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=2.188937
I20260812 06:18:21.226038 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3912,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:21.226557 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling MajorDeltaCompactionOp(c1095c9509404d84bd115a7950873094): perf score=1.000000
I20260812 06:18:21.386168 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: MajorDeltaCompactionOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.159s	user 0.110s	sys 0.049s Metrics: {"cfile_cache_miss":433,"cfile_cache_miss_bytes":20672367,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":463,"lbm_read_time_us":10506,"lbm_reads_lt_1ms":469,"lbm_write_time_us":29504,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":342,"threads_started":5,"update_count":2000}
I20260812 06:18:21.386875 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=10.126437
I20260812 06:18:21.423218 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.036s	user 0.013s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14872,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:21.423900 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=2.188937
I20260812 06:18:21.435686 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4446,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:21.436162 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling MajorDeltaCompactionOp(c1095c9509404d84bd115a7950873094): perf score=1.000000
I20260812 06:18:21.566339 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: MajorDeltaCompactionOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.130s	user 0.094s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":270,"lbm_read_time_us":9116,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25571,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17792,"update_count":2000}
I20260812 06:18:21.567102 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=10.126437
I20260812 06:18:21.617370 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.050s	user 0.032s	sys 0.000s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14741,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:21.617969 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=2.188937
I20260812 06:18:21.629136 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4116,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:21.629679 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling MajorDeltaCompactionOp(c1095c9509404d84bd115a7950873094): perf score=1.000000
I20260812 06:18:21.764292 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: MajorDeltaCompactionOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.134s	user 0.094s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":565,"lbm_read_time_us":9323,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25986,"lbm_writes_lt_1ms":443,"mutex_wait_us":286,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":66560,"update_count":2000}
I20260812 06:18:21.764989 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=10.126437
I20260812 06:18:21.823189 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.058s	user 0.044s	sys 0.010s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19788,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:21.823827 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=2.188937
I20260812 06:18:21.836089 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.012s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4759,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:21.836611 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling MajorDeltaCompactionOp(c1095c9509404d84bd115a7950873094): perf score=1.000000
I20260812 06:18:21.997615 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: MajorDeltaCompactionOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.161s	user 0.121s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":559,"lbm_read_time_us":11303,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25136,"lbm_writes_lt_1ms":443,"mutex_wait_us":117,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:18:21.998389 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=10.126437
I20260812 06:18:22.043627 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.045s	user 0.024s	sys 0.015s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17685,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:22.044148 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=2.188937
I20260812 06:18:22.055436 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4313,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.056283 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling MajorDeltaCompactionOp(c1095c9509404d84bd115a7950873094): perf score=1.000000
I20260812 06:18:22.188748 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: MajorDeltaCompactionOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.132s	user 0.093s	sys 0.038s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1071,"lbm_read_time_us":9423,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24970,"lbm_writes_lt_1ms":443,"mutex_wait_us":412,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":2000}
I20260812 06:18:22.189267 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=10.126437
I20260812 06:18:22.237931 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.048s	user 0.031s	sys 0.005s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16740,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:22.238492 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=2.188937
I20260812 06:18:22.251278 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4762,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.252197 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling MajorDeltaCompactionOp(c1095c9509404d84bd115a7950873094): perf score=1.000000
I20260812 06:18:22.382854 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: MajorDeltaCompactionOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.130s	user 0.115s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":340,"lbm_read_time_us":8201,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24968,"lbm_writes_lt_1ms":443,"mutex_wait_us":33,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17408,"update_count":2000}
I20260812 06:18:22.383708 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=10.126437
I20260812 06:18:22.429209 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.045s	user 0.022s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16576,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:22.429791 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=2.188937
I20260812 06:18:22.442445 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.012s	user 0.000s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4638,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.443037 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushMRSOp(c1095c9509404d84bd115a7950873094): perf score=1.000000
I20260812 06:18:22.476420 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushMRSOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.033s	user 0.028s	sys 0.004s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":263,"dirs.run_wall_time_us":1459,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2156,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:22.477116 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling LogGCOp(c1095c9509404d84bd115a7950873094): free 108535458 bytes of WAL
I20260812 06:18:22.477492 31266 log_reader.cc:385] T c1095c9509404d84bd115a7950873094: removed 11 log segments from log reader
I20260812 06:18:22.477557 31266 log.cc:1079] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/c1095c9509404d84bd115a7950873094/wal-000000003 (ops 12-16)
I20260812 06:18:22.477595 31266 log.cc:1079] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/c1095c9509404d84bd115a7950873094/wal-000000004 (ops 17-21)
I20260812 06:18:22.477623 31266 log.cc:1079] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/c1095c9509404d84bd115a7950873094/wal-000000005 (ops 22-26)
I20260812 06:18:22.477649 31266 log.cc:1079] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/c1095c9509404d84bd115a7950873094/wal-000000006 (ops 27-30)
I20260812 06:18:22.477677 31266 log.cc:1079] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/c1095c9509404d84bd115a7950873094/wal-000000007 (ops 31-35)
I20260812 06:18:22.477699 31266 log.cc:1079] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/c1095c9509404d84bd115a7950873094/wal-000000008 (ops 36-40)
I20260812 06:18:22.477720 31266 log.cc:1079] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/c1095c9509404d84bd115a7950873094/wal-000000009 (ops 41-45)
I20260812 06:18:22.477741 31266 log.cc:1079] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/c1095c9509404d84bd115a7950873094/wal-000000010 (ops 46-50)
I20260812 06:18:22.477762 31266 log.cc:1079] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/c1095c9509404d84bd115a7950873094/wal-000000011 (ops 51-54)
I20260812 06:18:22.477793 31266 log.cc:1079] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/c1095c9509404d84bd115a7950873094/wal-000000012 (ops 55-59)
I20260812 06:18:22.477835 31266 log.cc:1079] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/c1095c9509404d84bd115a7950873094/wal-000000013 (ops 60-64)
I20260812 06:18:22.503713 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: LogGCOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:22.504195 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=2.188937
I20260812 06:18:22.525887 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.022s	user 0.004s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5961,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.526546 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling LogGCOp(c1095c9509404d84bd115a7950873094): free 11564875 bytes of WAL
I20260812 06:18:22.526947 31266 log_reader.cc:385] T c1095c9509404d84bd115a7950873094: removed 1 log segments from log reader
I20260812 06:18:22.526998 31266 log.cc:1079] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/c1095c9509404d84bd115a7950873094/wal-000000014 (ops 65-68)
I20260812 06:18:22.529163 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: LogGCOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:22.529490 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=2.188937
I20260812 06:18:22.542073 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4048,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.542544 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling MajorDeltaCompactionOp(c1095c9509404d84bd115a7950873094): perf score=1.000000
I20260812 06:18:22.722939 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: MajorDeltaCompactionOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.180s	user 0.142s	sys 0.038s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877338,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":500,"lbm_read_time_us":12934,"lbm_reads_lt_1ms":670,"lbm_write_time_us":36114,"lbm_writes_lt_1ms":643,"mutex_wait_us":20,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":737664,"thread_start_us":84,"threads_started":1,"update_count":3000}
I20260812 06:18:22.723685 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling UndoDeltaBlockGCOp(c1095c9509404d84bd115a7950873094): 447 bytes on disk
I20260812 06:18:22.724179 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: UndoDeltaBlockGCOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":98,"lbm_reads_lt_1ms":4}
I20260812 06:18:22.724900 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=14.095187
I20260812 06:18:22.795943 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.071s	user 0.037s	sys 0.033s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":32121,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:18:22.796578 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=2.188937
I20260812 06:18:22.814289 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.018s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6106,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.814870 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling MajorDeltaCompactionOp(c1095c9509404d84bd115a7950873094): perf score=1.000000
I20260812 06:18:22.972271 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: MajorDeltaCompactionOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.157s	user 0.102s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":256,"lbm_read_time_us":8704,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29942,"lbm_writes_lt_1ms":543,"mutex_wait_us":55,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":104064,"update_count":2500}
I20260812 06:18:22.973075 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=14.095187
I20260812 06:18:23.031441 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.058s	user 0.043s	sys 0.012s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":24847,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:23.032071 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling MajorDeltaCompactionOp(c1095c9509404d84bd115a7950873094): perf score=1.000000
I20260812 06:18:23.194589 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: MajorDeltaCompactionOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.162s	user 0.102s	sys 0.057s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672160,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":569,"lbm_read_time_us":11736,"lbm_reads_lt_1ms":463,"lbm_write_time_us":27461,"lbm_writes_lt_1ms":443,"mutex_wait_us":239,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2000}
I20260812 06:18:23.195202 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=14.095187
I20260812 06:18:23.251695 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.056s	user 0.034s	sys 0.020s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":24960,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:23.252454 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=2.188937
I20260812 06:18:23.265112 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4100,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:23.265895 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling MajorDeltaCompactionOp(c1095c9509404d84bd115a7950873094): perf score=1.000000
I20260812 06:18:23.465116 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: MajorDeltaCompactionOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.199s	user 0.144s	sys 0.047s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":668,"lbm_read_time_us":12290,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31527,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6912,"update_count":2500}
I20260812 06:18:23.465839 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=14.095187
I20260812 06:18:23.522528 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.057s	user 0.035s	sys 0.015s Metrics: {"bytes_written":16409907,"delete_count":0,"lbm_write_time_us":23658,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:23.523137 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=2.188937
I20260812 06:18:23.539283 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.016s	user 0.012s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6073,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:23.539950 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling MajorDeltaCompactionOp(c1095c9509404d84bd115a7950873094): perf score=1.000000
I20260812 06:18:23.708743 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: MajorDeltaCompactionOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.169s	user 0.115s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774693,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":671,"lbm_read_time_us":10037,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32717,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2500}
I20260812 06:18:23.709527 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=11.118625
I20260812 06:18:23.753620 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.044s	user 0.025s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":19059,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:23.754204 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=2.188937
I20260812 06:18:23.779551 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.025s	user 0.006s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5688,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:23.780066 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=2.188937
I20260812 06:18:23.791887 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.012s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4460,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:23.792443 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling MajorDeltaCompactionOp(c1095c9509404d84bd115a7950873094): perf score=1.000000
I20260812 06:18:23.954082 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: MajorDeltaCompactionOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.161s	user 0.130s	sys 0.026s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":326,"lbm_read_time_us":12536,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30334,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2500}
I20260812 06:18:23.954873 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=11.118625
I20260812 06:18:23.999366 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.044s	user 0.020s	sys 0.020s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15914,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:24.000074 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=2.188937
I20260812 06:18:24.019806 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.020s	user 0.015s	sys 0.001s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":6884,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.020476 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=2.188937
I20260812 06:18:24.035760 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.015s	user 0.013s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5961,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:24.036523 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushMRSOp(c1095c9509404d84bd115a7950873094): perf score=1.000000
I20260812 06:18:24.072026 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushMRSOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.035s	user 0.030s	sys 0.004s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":234,"dirs.run_wall_time_us":1549,"drs_written":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2141,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:24.072857 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling LogGCOp(c1095c9509404d84bd115a7950873094): free 117302571 bytes of WAL
I20260812 06:18:24.073143 31266 log_reader.cc:385] T c1095c9509404d84bd115a7950873094: removed 12 log segments from log reader
I20260812 06:18:24.073222 31266 log.cc:1079] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/c1095c9509404d84bd115a7950873094/wal-000000015 (ops 69-73)
I20260812 06:18:24.073263 31266 log.cc:1079] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/c1095c9509404d84bd115a7950873094/wal-000000016 (ops 74-78)
I20260812 06:18:24.073292 31266 log.cc:1079] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/c1095c9509404d84bd115a7950873094/wal-000000017 (ops 79-83)
I20260812 06:18:24.073314 31266 log.cc:1079] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/c1095c9509404d84bd115a7950873094/wal-000000018 (ops 84-88)
I20260812 06:18:24.073336 31266 log.cc:1079] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/c1095c9509404d84bd115a7950873094/wal-000000019 (ops 89-92)
I20260812 06:18:24.073357 31266 log.cc:1079] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/c1095c9509404d84bd115a7950873094/wal-000000020 (ops 93-97)
I20260812 06:18:24.073379 31266 log.cc:1079] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/c1095c9509404d84bd115a7950873094/wal-000000021 (ops 98-102)
I20260812 06:18:24.073402 31266 log.cc:1079] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/c1095c9509404d84bd115a7950873094/wal-000000022 (ops 103-107)
I20260812 06:18:24.073428 31266 log.cc:1079] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/c1095c9509404d84bd115a7950873094/wal-000000023 (ops 108-112)
I20260812 06:18:24.073452 31266 log.cc:1079] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/c1095c9509404d84bd115a7950873094/wal-000000024 (ops 113-116)
I20260812 06:18:24.073474 31266 log.cc:1079] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/c1095c9509404d84bd115a7950873094/wal-000000025 (ops 117-121)
I20260812 06:18:24.073495 31266 log.cc:1079] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/c1095c9509404d84bd115a7950873094/wal-000000026 (ops 122-126)
I20260812 06:18:24.103531 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: LogGCOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.030s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:18:24.104005 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling UndoDeltaBlockGCOp(c1095c9509404d84bd115a7950873094): 483 bytes on disk
I20260812 06:18:24.104465 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: UndoDeltaBlockGCOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:18:24.105041 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=2.188937
I20260812 06:18:24.128619 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.023s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4743,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.129135 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=2.188937
I20260812 06:18:24.141813 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4575,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.142493 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling MajorDeltaCompactionOp(c1095c9509404d84bd115a7950873094): perf score=1.000000
I20260812 06:18:24.413766 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: MajorDeltaCompactionOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.271s	user 0.147s	sys 0.107s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979862,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":372,"lbm_read_time_us":17604,"lbm_reads_lt_1ms":775,"lbm_write_time_us":39899,"lbm_writes_lt_1ms":743,"mutex_wait_us":111,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3968,"thread_start_us":79,"threads_started":1,"update_count":3500}
I20260812 06:18:24.414408 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=18.063937
I20260812 06:18:24.481354 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.067s	user 0.048s	sys 0.015s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":29384,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:24.481984 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=2.188937
I20260812 06:18:24.499686 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.017s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6891,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.501048 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling MajorDeltaCompactionOp(c1095c9509404d84bd115a7950873094): perf score=1.000000
I20260812 06:18:24.724839 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: MajorDeltaCompactionOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.224s	user 0.142s	sys 0.067s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":473,"lbm_read_time_us":14455,"lbm_reads_lt_1ms":672,"lbm_write_time_us":36087,"lbm_writes_lt_1ms":643,"mutex_wait_us":2,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":3000}
I20260812 06:18:24.726008 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=18.063937
I20260812 06:18:24.804811 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.078s	user 0.046s	sys 0.024s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":33163,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:18:24.805444 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=2.188937
I20260812 06:18:24.816141 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3927,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.817998 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling MajorDeltaCompactionOp(c1095c9509404d84bd115a7950873094): perf score=1.000000
I20260812 06:18:25.038085 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: MajorDeltaCompactionOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.220s	user 0.147s	sys 0.071s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":890,"lbm_read_time_us":14980,"lbm_reads_lt_1ms":672,"lbm_write_time_us":38177,"lbm_writes_lt_1ms":643,"mutex_wait_us":364,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":18560,"update_count":3000}
I20260812 06:18:25.038932 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=15.087375
I20260812 06:18:25.089843 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.051s	user 0.035s	sys 0.013s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":23117,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:25.090456 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=2.188937
I20260812 06:18:25.103690 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5176,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:25.104202 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling MajorDeltaCompactionOp(c1095c9509404d84bd115a7950873094): perf score=1.000000
I20260812 06:18:25.291827 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: MajorDeltaCompactionOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.187s	user 0.132s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774676,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":305,"lbm_read_time_us":12727,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31989,"lbm_writes_lt_1ms":543,"mutex_wait_us":81,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2500}
I20260812 06:18:25.292573 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=14.095187
I20260812 06:18:25.356318 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.064s	user 0.035s	sys 0.027s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":23947,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:25.356992 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=2.188937
I20260812 06:18:25.369824 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.013s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4590,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.370460 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling MajorDeltaCompactionOp(c1095c9509404d84bd115a7950873094): perf score=1.000000
I20260812 06:18:25.569685 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: MajorDeltaCompactionOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.199s	user 0.121s	sys 0.067s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":566,"lbm_read_time_us":12175,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32927,"lbm_writes_lt_1ms":543,"mutex_wait_us":323,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":28160,"update_count":2500}
I20260812 06:18:25.570392 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=14.095187
I20260812 06:18:25.631013 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.060s	user 0.036s	sys 0.016s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":19405,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:25.631660 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=2.188937
I20260812 06:18:25.644403 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4898,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.644989 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushMRSOp(c1095c9509404d84bd115a7950873094): perf score=1.000000
I20260812 06:18:25.689229 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushMRSOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.044s	user 0.026s	sys 0.003s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":283,"dirs.run_wall_time_us":1809,"drs_written":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1712,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:25.690325 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling LogGCOp(c1095c9509404d84bd115a7950873094): free 124257441 bytes of WAL
I20260812 06:18:25.690678 31266 log_reader.cc:385] T c1095c9509404d84bd115a7950873094: removed 12 log segments from log reader
I20260812 06:18:25.690752 31266 log.cc:1079] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/c1095c9509404d84bd115a7950873094/wal-000000027 (ops 127-131)
I20260812 06:18:25.690805 31266 log.cc:1079] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/c1095c9509404d84bd115a7950873094/wal-000000028 (ops 132-136)
I20260812 06:18:25.690845 31266 log.cc:1079] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/c1095c9509404d84bd115a7950873094/wal-000000029 (ops 137-141)
I20260812 06:18:25.690882 31266 log.cc:1079] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/c1095c9509404d84bd115a7950873094/wal-000000030 (ops 142-146)
I20260812 06:18:25.690922 31266 log.cc:1079] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/c1095c9509404d84bd115a7950873094/wal-000000031 (ops 147-151)
I20260812 06:18:25.690959 31266 log.cc:1079] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/c1095c9509404d84bd115a7950873094/wal-000000032 (ops 152-156)
I20260812 06:18:25.690999 31266 log.cc:1079] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/c1095c9509404d84bd115a7950873094/wal-000000033 (ops 157-160)
I20260812 06:18:25.691036 31266 log.cc:1079] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/c1095c9509404d84bd115a7950873094/wal-000000034 (ops 161-165)
I20260812 06:18:25.691074 31266 log.cc:1079] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/c1095c9509404d84bd115a7950873094/wal-000000035 (ops 166-170)
I20260812 06:18:25.691114 31266 log.cc:1079] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/c1095c9509404d84bd115a7950873094/wal-000000036 (ops 171-175)
I20260812 06:18:25.691151 31266 log.cc:1079] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/c1095c9509404d84bd115a7950873094/wal-000000037 (ops 176-180)
I20260812 06:18:25.691190 31266 log.cc:1079] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: Deleting log segment in path: /tmp/dist-test-taskGuEMNb/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515494560124-30943-0/minicluster-data/ts-0-root/wals/c1095c9509404d84bd115a7950873094/wal-000000038 (ops 181-185)
I20260812 06:18:25.719662 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: LogGCOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.029s	user 0.001s	sys 0.027s Metrics: {}
I20260812 06:18:25.720227 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling UndoDeltaBlockGCOp(c1095c9509404d84bd115a7950873094): 462 bytes on disk
I20260812 06:18:25.720902 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: UndoDeltaBlockGCOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:18:25.721553 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=3.181125
I20260812 06:18:25.744015 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.022s	user 0.000s	sys 0.013s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5775,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:25.744602 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=2.188937
I20260812 06:18:25.760499 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.016s	user 0.001s	sys 0.013s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5910,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:25.763209 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling MajorDeltaCompactionOp(c1095c9509404d84bd115a7950873094): perf score=1.000000
I20260812 06:18:26.025521 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: MajorDeltaCompactionOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.262s	user 0.164s	sys 0.092s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979743,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":824,"lbm_read_time_us":20969,"lbm_reads_lt_1ms":774,"lbm_write_time_us":41980,"lbm_writes_lt_1ms":743,"mutex_wait_us":324,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":12672,"thread_start_us":90,"threads_started":1,"update_count":3500}
I20260812 06:18:26.026307 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=18.063937
I20260812 06:18:26.084190 30943 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.186s	user 1.902s	sys 0.180s
I20260812 06:18:26.089396 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.063s	user 0.034s	sys 0.027s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":29813,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:26.089890 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094): perf score=2.188937
I20260812 06:18:26.099938 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: FlushDeltaMemStoresOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3955,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:26.100590 31334 maintenance_manager.cc:419] P dfea94cdbe654610a4d3730a65cdaea3: Scheduling MajorDeltaCompactionOp(c1095c9509404d84bd115a7950873094): perf score=1.000000
I20260812 06:18:26.123492 30943 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.039s	user 0.002s	sys 0.000s
I20260812 06:18:26.124046 30943 tablet_server.cc:179] TabletServer@127.30.55.193:0 shutting down...
I20260812 06:18:26.276566 31266 maintenance_manager.cc:643] P dfea94cdbe654610a4d3730a65cdaea3: MajorDeltaCompactionOp(c1095c9509404d84bd115a7950873094) complete. Timing: real 0.176s	user 0.120s	sys 0.055s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4262390,"cfile_cache_miss":602,"cfile_cache_miss_bytes":24614713,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":504,"lbm_read_time_us":10262,"lbm_reads_lt_1ms":618,"lbm_write_time_us":31157,"lbm_writes_lt_1ms":643,"mutex_wait_us":74,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":37504,"update_count":3000}
I20260812 06:18:26.278286 30943 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:26.278614 30943 tablet_replica.cc:333] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3: stopping tablet replica
I20260812 06:18:26.278805 30943 raft_consensus.cc:2243] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:26.279024 30943 raft_consensus.cc:2272] T c1095c9509404d84bd115a7950873094 P dfea94cdbe654610a4d3730a65cdaea3 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:26.283222 30943 tablet_server.cc:196] TabletServer@127.30.55.193:0 shutdown complete.
I20260812 06:18:26.333673 30943 master.cc:562] Master@127.30.55.254:34451 shutting down...
I20260812 06:18:26.338316 30943 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 98c0bb8d751647d5bc5d20649e4b31ce [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:26.338531 30943 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 98c0bb8d751647d5bc5d20649e4b31ce [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:26.338678 30943 tablet_replica.cc:333] T 00000000000000000000000000000000 P 98c0bb8d751647d5bc5d20649e4b31ce: stopping tablet replica
I20260812 06:18:26.351516 30943 master.cc:584] Master@127.30.55.254:34451 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5844 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11881 ms total)

[----------] Global test environment tear-down
[==========] 2 tests from 1 test suite ran. (11881 ms total)
[  PASSED  ] 2 tests.
