[==========] 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:17:43.151110  8332 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.8.35.62:46611
I20260812 06:17:43.152143  8332 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:17:43.152776  8332 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:43.159471  8343 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:17:43.159535  8338 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:17:43.159660  8332 server_base.cc:1061] running on GCE node
W20260812 06:17:43.159884  8340 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:17:43.160462  8332 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:43.160590  8332 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:17:43.160655  8332 hybrid_clock.cc:648] HybridClock initialized: now 1786515463160651 us; error 0 us; skew 500 ppm
I20260812 06:17:43.162544  8332 webserver.cc:533] Webserver started at http://127.8.35.62:42261/ using document root <none> and password file <none>
I20260812 06:17:43.163178  8332 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:43.163265  8332 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:43.163511  8332 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:43.165236  8332 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/master-0-root/instance:
uuid: "0fef162c1ce04c01a06ffc201933a492"
format_stamp: "Formatted at 2026-08-12 06:17:43 on dist-test-slave-zh2d"
I20260812 06:17:43.168730  8332 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:43.170800  8349 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:17:43.171841  8332 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:43.171973  8332 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/master-0-root
uuid: "0fef162c1ce04c01a06ffc201933a492"
format_stamp: "Formatted at 2026-08-12 06:17:43 on dist-test-slave-zh2d"
I20260812 06:17:43.172076  8332 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-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:17:43.182713  8332 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:43.183326  8332 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:17:43.183516  8332 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:43.191766  8332 rpc_server.cc:307] RPC server started. Bound to: 127.8.35.62:46611
I20260812 06:17:43.191769  8437 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.35.62:46611 every 8 connection(s)
I20260812 06:17:43.194103  8439 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:17:43.199405  8439 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0fef162c1ce04c01a06ffc201933a492: Bootstrap starting.
I20260812 06:17:43.201862  8439 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 0fef162c1ce04c01a06ffc201933a492: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:43.202733  8439 log.cc:826] T 00000000000000000000000000000000 P 0fef162c1ce04c01a06ffc201933a492: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:43.204397  8439 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0fef162c1ce04c01a06ffc201933a492: No bootstrap required, opened a new log
I20260812 06:17:43.207195  8439 raft_consensus.cc:359] T 00000000000000000000000000000000 P 0fef162c1ce04c01a06ffc201933a492 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0fef162c1ce04c01a06ffc201933a492" member_type: VOTER }
I20260812 06:17:43.207355  8439 raft_consensus.cc:385] T 00000000000000000000000000000000 P 0fef162c1ce04c01a06ffc201933a492 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:43.207397  8439 raft_consensus.cc:740] T 00000000000000000000000000000000 P 0fef162c1ce04c01a06ffc201933a492 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0fef162c1ce04c01a06ffc201933a492, State: Initialized, Role: FOLLOWER
I20260812 06:17:43.207911  8439 consensus_queue.cc:260] T 00000000000000000000000000000000 P 0fef162c1ce04c01a06ffc201933a492 [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: "0fef162c1ce04c01a06ffc201933a492" member_type: VOTER }
I20260812 06:17:43.208053  8439 raft_consensus.cc:399] T 00000000000000000000000000000000 P 0fef162c1ce04c01a06ffc201933a492 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:43.208093  8439 raft_consensus.cc:493] T 00000000000000000000000000000000 P 0fef162c1ce04c01a06ffc201933a492 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:43.208177  8439 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 0fef162c1ce04c01a06ffc201933a492 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:43.208983  8439 raft_consensus.cc:515] T 00000000000000000000000000000000 P 0fef162c1ce04c01a06ffc201933a492 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0fef162c1ce04c01a06ffc201933a492" member_type: VOTER }
I20260812 06:17:43.209383  8439 leader_election.cc:304] T 00000000000000000000000000000000 P 0fef162c1ce04c01a06ffc201933a492 [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: 0fef162c1ce04c01a06ffc201933a492; no voters: 
I20260812 06:17:43.209656  8439 leader_election.cc:290] T 00000000000000000000000000000000 P 0fef162c1ce04c01a06ffc201933a492 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:43.209842  8445 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 0fef162c1ce04c01a06ffc201933a492 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:43.210110  8445 raft_consensus.cc:697] T 00000000000000000000000000000000 P 0fef162c1ce04c01a06ffc201933a492 [term 1 LEADER]: Becoming Leader. State: Replica: 0fef162c1ce04c01a06ffc201933a492, State: Running, Role: LEADER
I20260812 06:17:43.210547  8445 consensus_queue.cc:237] T 00000000000000000000000000000000 P 0fef162c1ce04c01a06ffc201933a492 [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: "0fef162c1ce04c01a06ffc201933a492" member_type: VOTER }
I20260812 06:17:43.210701  8439 sys_catalog.cc:565] T 00000000000000000000000000000000 P 0fef162c1ce04c01a06ffc201933a492 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:43.212616  8446 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0fef162c1ce04c01a06ffc201933a492 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "0fef162c1ce04c01a06ffc201933a492" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0fef162c1ce04c01a06ffc201933a492" member_type: VOTER } }
I20260812 06:17:43.212752  8446 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0fef162c1ce04c01a06ffc201933a492 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:43.212616  8451 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0fef162c1ce04c01a06ffc201933a492 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 0fef162c1ce04c01a06ffc201933a492. Latest consensus state: current_term: 1 leader_uuid: "0fef162c1ce04c01a06ffc201933a492" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0fef162c1ce04c01a06ffc201933a492" member_type: VOTER } }
I20260812 06:17:43.213125  8451 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0fef162c1ce04c01a06ffc201933a492 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:43.213153  8332 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:17:43.215233  8468 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 0fef162c1ce04c01a06ffc201933a492: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:17:43.215301  8468 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:17:43.215382  8467 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:43.216105  8467 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:43.221077  8467 catalog_manager.cc:1383] Generated new cluster ID: a9cb2318b9494b1ca975a3e368b0922d
I20260812 06:17:43.221143  8467 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:43.229234  8467 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:43.230381  8467 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:43.244118  8467 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 0fef162c1ce04c01a06ffc201933a492: Generated new TSK 0
I20260812 06:17:43.244925  8467 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:43.278015  8332 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:43.281116  8476 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:17:43.281112  8475 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:17:43.281111  8479 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:17:43.281437  8332 server_base.cc:1061] running on GCE node
I20260812 06:17:43.281651  8332 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:43.281711  8332 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:17:43.281737  8332 hybrid_clock.cc:648] HybridClock initialized: now 1786515463281736 us; error 0 us; skew 500 ppm
I20260812 06:17:43.282717  8332 webserver.cc:533] Webserver started at http://127.8.35.1:34319/ using document root <none> and password file <none>
I20260812 06:17:43.282919  8332 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:43.283016  8332 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:43.283106  8332 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:43.283540  8332 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root/instance:
uuid: "ecfbfd452b5648d6ad748e61e99e1708"
format_stamp: "Formatted at 2026-08-12 06:17:43 on dist-test-slave-zh2d"
I20260812 06:17:43.285175  8332 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:43.286247  8485 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:17:43.286515  8332 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:43.286584  8332 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root
uuid: "ecfbfd452b5648d6ad748e61e99e1708"
format_stamp: "Formatted at 2026-08-12 06:17:43 on dist-test-slave-zh2d"
I20260812 06:17:43.286670  8332 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-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:17:43.295600  8332 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:43.296006  8332 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:43.296537  8332 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:43.297475  8332 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:43.297528  8332 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:43.297593  8332 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:43.297636  8332 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:43.304699  8332 rpc_server.cc:307] RPC server started. Bound to: 127.8.35.1:44543
I20260812 06:17:43.304751  8574 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.35.1:44543 every 8 connection(s)
I20260812 06:17:43.318379  8575 heartbeater.cc:344] Connected to a master server at 127.8.35.62:46611
I20260812 06:17:43.318642  8575 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:43.319096  8575 heartbeater.cc:507] Master 127.8.35.62:46611 requested a full tablet report, sending...
I20260812 06:17:43.320554  8370 ts_manager.cc:194] Registered new tserver with Master: ecfbfd452b5648d6ad748e61e99e1708 (127.8.35.1:44543)
I20260812 06:17:43.321025  8332 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01564813s
I20260812 06:17:43.321852  8370 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:35644
I20260812 06:17:43.330786  8370 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:35660:
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:17:43.344424  8525 tablet_service.cc:1511] Processing CreateTablet for tablet 7e9e9caaa7154a9492c957d61929619f (DEFAULT_TABLE table=heavy-update-compaction-test [id=7e0f3e0762de4c9a862cbec27b0ca6bf]), partition=
I20260812 06:17:43.345014  8525 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 7e9e9caaa7154a9492c957d61929619f. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:43.347363  8595 tablet_bootstrap.cc:492] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Bootstrap starting.
I20260812 06:17:43.348500  8595 tablet_bootstrap.cc:654] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:43.349757  8595 tablet_bootstrap.cc:492] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: No bootstrap required, opened a new log
I20260812 06:17:43.349876  8595 ts_tablet_manager.cc:1403] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:43.350335  8595 raft_consensus.cc:359] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ecfbfd452b5648d6ad748e61e99e1708" member_type: VOTER last_known_addr { host: "127.8.35.1" port: 44543 } }
I20260812 06:17:43.350466  8595 raft_consensus.cc:385] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:43.350533  8595 raft_consensus.cc:740] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ecfbfd452b5648d6ad748e61e99e1708, State: Initialized, Role: FOLLOWER
I20260812 06:17:43.350703  8595 consensus_queue.cc:260] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708 [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: "ecfbfd452b5648d6ad748e61e99e1708" member_type: VOTER last_known_addr { host: "127.8.35.1" port: 44543 } }
I20260812 06:17:43.350813  8595 raft_consensus.cc:399] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:43.350863  8595 raft_consensus.cc:493] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:43.350919  8595 raft_consensus.cc:3060] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:43.351653  8595 raft_consensus.cc:515] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ecfbfd452b5648d6ad748e61e99e1708" member_type: VOTER last_known_addr { host: "127.8.35.1" port: 44543 } }
I20260812 06:17:43.351809  8595 leader_election.cc:304] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708 [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: ecfbfd452b5648d6ad748e61e99e1708; no voters: 
I20260812 06:17:43.352032  8595 leader_election.cc:290] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:43.352319  8599 raft_consensus.cc:2804] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:43.352432  8595 ts_tablet_manager.cc:1434] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:17:43.352646  8599 raft_consensus.cc:697] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708 [term 1 LEADER]: Becoming Leader. State: Replica: ecfbfd452b5648d6ad748e61e99e1708, State: Running, Role: LEADER
I20260812 06:17:43.352901  8575 heartbeater.cc:499] Master 127.8.35.62:46611 was elected leader, sending a full tablet report...
I20260812 06:17:43.352864  8599 consensus_queue.cc:237] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708 [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: "ecfbfd452b5648d6ad748e61e99e1708" member_type: VOTER last_known_addr { host: "127.8.35.1" port: 44543 } }
I20260812 06:17:43.355682  8370 catalog_manager.cc:5719] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708 reported cstate change: term changed from 0 to 1, leader changed from <none> to ecfbfd452b5648d6ad748e61e99e1708 (127.8.35.1). New cstate: current_term: 1 leader_uuid: "ecfbfd452b5648d6ad748e61e99e1708" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ecfbfd452b5648d6ad748e61e99e1708" member_type: VOTER last_known_addr { host: "127.8.35.1" port: 44543 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:43.433100  8332 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.068s	user 0.028s	sys 0.006s
I20260812 06:17:43.556051  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushMRSOp(7e9e9caaa7154a9492c957d61929619f): perf score=15.086190
I20260812 06:17:43.699976  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushMRSOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.144s	user 0.112s	sys 0.028s Metrics: {"bytes_written":8738395,"cfile_init":1,"compiler_manager_pool.queue_time_us":303,"delete_count":0,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":200,"dirs.run_wall_time_us":770,"drs_written":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4,"lbm_write_time_us":35459,"lbm_writes_lt_1ms":580,"mutex_wait_us":699,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":199040,"thread_start_us":163,"threads_started":1,"update_count":1065}
I20260812 06:17:43.701229  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling LogGCOp(7e9e9caaa7154a9492c957d61929619f): free 20743880 bytes of WAL
I20260812 06:17:43.701545  8493 log_reader.cc:385] T 7e9e9caaa7154a9492c957d61929619f: removed 2 log segments from log reader
I20260812 06:17:43.701625  8493 log.cc:1079] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/7e9e9caaa7154a9492c957d61929619f/wal-000000001 (ops 1-6)
I20260812 06:17:43.701700  8493 log.cc:1079] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/7e9e9caaa7154a9492c957d61929619f/wal-000000002 (ops 7-11)
I20260812 06:17:43.708216  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: LogGCOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.007s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:43.708607  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=1.196750
I20260812 06:17:43.722440  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3159080,"delete_count":0,"lbm_write_time_us":4627,"lbm_writes_lt_1ms":80,"reinsert_count":0,"update_count":385}
I20260812 06:17:43.722975  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling UndoDeltaBlockGCOp(7e9e9caaa7154a9492c957d61929619f): 12719216 bytes on disk
I20260812 06:17:43.723531  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: UndoDeltaBlockGCOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:17:43.723958  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling MajorDeltaCompactionOp(7e9e9caaa7154a9492c957d61929619f): perf score=1.000000
I20260812 06:17:43.851109  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: MajorDeltaCompactionOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.127s	user 0.089s	sys 0.027s Metrics: {"cfile_cache_miss":322,"cfile_cache_miss_bytes":16159603,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":673,"lbm_read_time_us":6993,"lbm_reads_lt_1ms":350,"lbm_write_time_us":20586,"lbm_writes_lt_1ms":333,"peak_mem_usage":36812022,"reinsert_count":0,"spinlock_wait_cycles":2688,"thread_start_us":348,"threads_started":5,"update_count":1450}
I20260812 06:17:43.851759  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=10.126437
I20260812 06:17:43.898213  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.046s	user 0.032s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16704,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:43.898727  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=2.188937
I20260812 06:17:43.910490  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4357,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:43.911139  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling MajorDeltaCompactionOp(7e9e9caaa7154a9492c957d61929619f): perf score=1.000000
I20260812 06:17:44.041189  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: MajorDeltaCompactionOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.130s	user 0.108s	sys 0.021s 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":465,"lbm_read_time_us":9720,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24834,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:44.041731  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=10.126437
I20260812 06:17:44.105515  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.064s	user 0.025s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17964,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:44.106168  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=2.188937
I20260812 06:17:44.118475  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4820,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:44.119086  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling MajorDeltaCompactionOp(7e9e9caaa7154a9492c957d61929619f): perf score=1.000000
I20260812 06:17:44.287693  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: MajorDeltaCompactionOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.168s	user 0.126s	sys 0.039s 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":633,"lbm_read_time_us":11631,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28641,"lbm_writes_lt_1ms":443,"mutex_wait_us":71,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18432,"update_count":2000}
I20260812 06:17:44.288244  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=10.126437
I20260812 06:17:44.341048  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.053s	user 0.022s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18820,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:44.341554  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=2.188937
I20260812 06:17:44.352823  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4263,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:44.353451  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling MajorDeltaCompactionOp(7e9e9caaa7154a9492c957d61929619f): perf score=1.000000
I20260812 06:17:44.490489  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: MajorDeltaCompactionOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.137s	user 0.098s	sys 0.038s 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":263,"lbm_read_time_us":10613,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27491,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2000}
I20260812 06:17:44.491088  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=10.126437
I20260812 06:17:44.541502  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.050s	user 0.025s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19253,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:44.541966  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=2.188937
I20260812 06:17:44.553196  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4222,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:44.553864  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling MajorDeltaCompactionOp(7e9e9caaa7154a9492c957d61929619f): perf score=1.000000
I20260812 06:17:44.683422  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: MajorDeltaCompactionOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.129s	user 0.120s	sys 0.008s 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":846,"lbm_read_time_us":10332,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27650,"lbm_writes_lt_1ms":443,"mutex_wait_us":399,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18176,"update_count":2000}
I20260812 06:17:44.684093  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=10.126437
I20260812 06:17:44.746528  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.062s	user 0.024s	sys 0.022s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":19274,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:44.747068  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=2.188937
I20260812 06:17:44.774461  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.027s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5781,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:44.774960  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=2.188937
I20260812 06:17:44.787102  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4897,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:44.787619  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling MajorDeltaCompactionOp(7e9e9caaa7154a9492c957d61929619f): perf score=1.000000
I20260812 06:17:44.996721  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: MajorDeltaCompactionOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.209s	user 0.138s	sys 0.061s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774810,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":586,"lbm_read_time_us":15241,"lbm_reads_lt_1ms":573,"lbm_write_time_us":36065,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":2500}
I20260812 06:17:44.997392  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=14.095187
I20260812 06:17:45.059440  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.062s	user 0.029s	sys 0.029s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24452,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:45.060077  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=2.188937
I20260812 06:17:45.073243  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5175,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:45.073715  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushMRSOp(7e9e9caaa7154a9492c957d61929619f): perf score=1.000000
I20260812 06:17:45.114322  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushMRSOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.040s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":277,"dirs.run_wall_time_us":1479,"drs_written":1,"lbm_read_time_us":94,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1704,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:45.115222  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling LogGCOp(7e9e9caaa7154a9492c957d61929619f): free 112239317 bytes of WAL
I20260812 06:17:45.115463  8493 log_reader.cc:385] T 7e9e9caaa7154a9492c957d61929619f: removed 11 log segments from log reader
I20260812 06:17:45.115509  8493 log.cc:1079] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/7e9e9caaa7154a9492c957d61929619f/wal-000000003 (ops 12-16)
I20260812 06:17:45.115540  8493 log.cc:1079] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/7e9e9caaa7154a9492c957d61929619f/wal-000000004 (ops 17-21)
I20260812 06:17:45.115604  8493 log.cc:1079] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/7e9e9caaa7154a9492c957d61929619f/wal-000000005 (ops 22-26)
I20260812 06:17:45.115640  8493 log.cc:1079] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/7e9e9caaa7154a9492c957d61929619f/wal-000000006 (ops 27-31)
I20260812 06:17:45.115680  8493 log.cc:1079] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/7e9e9caaa7154a9492c957d61929619f/wal-000000007 (ops 32-36)
I20260812 06:17:45.115720  8493 log.cc:1079] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/7e9e9caaa7154a9492c957d61929619f/wal-000000008 (ops 37-41)
I20260812 06:17:45.115760  8493 log.cc:1079] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/7e9e9caaa7154a9492c957d61929619f/wal-000000009 (ops 42-46)
I20260812 06:17:45.115799  8493 log.cc:1079] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/7e9e9caaa7154a9492c957d61929619f/wal-000000010 (ops 47-51)
I20260812 06:17:45.115839  8493 log.cc:1079] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/7e9e9caaa7154a9492c957d61929619f/wal-000000011 (ops 52-56)
I20260812 06:17:45.115885  8493 log.cc:1079] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/7e9e9caaa7154a9492c957d61929619f/wal-000000012 (ops 57-60)
I20260812 06:17:45.115929  8493 log.cc:1079] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/7e9e9caaa7154a9492c957d61929619f/wal-000000013 (ops 61-65)
I20260812 06:17:45.140596  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: LogGCOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.025s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:17:45.141083  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling UndoDeltaBlockGCOp(7e9e9caaa7154a9492c957d61929619f): 447 bytes on disk
I20260812 06:17:45.141579  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: UndoDeltaBlockGCOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:17:45.142061  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=2.188937
I20260812 06:17:45.167167  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.025s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5845,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:45.167651  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=2.188937
I20260812 06:17:45.179070  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4245,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:45.179821  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling MajorDeltaCompactionOp(7e9e9caaa7154a9492c957d61929619f): perf score=1.000000
I20260812 06:17:45.424247  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: MajorDeltaCompactionOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.244s	user 0.141s	sys 0.092s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979752,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":599,"lbm_read_time_us":18803,"lbm_reads_lt_1ms":774,"lbm_write_time_us":44271,"lbm_writes_lt_1ms":743,"mutex_wait_us":337,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":78,"threads_started":1,"update_count":3500}
I20260812 06:17:45.424893  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=18.063937
I20260812 06:17:45.485271  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.060s	user 0.043s	sys 0.017s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":27605,"lbm_writes_lt_1ms":503,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2500}
I20260812 06:17:45.485823  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=2.188937
I20260812 06:17:45.502552  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.017s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6381,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:45.503343  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling MajorDeltaCompactionOp(7e9e9caaa7154a9492c957d61929619f): perf score=1.000000
I20260812 06:17:45.681356  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: MajorDeltaCompactionOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.178s	user 0.124s	sys 0.052s 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":937,"lbm_read_time_us":15294,"lbm_reads_lt_1ms":672,"lbm_write_time_us":37222,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":3000}
I20260812 06:17:45.681919  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=14.095187
I20260812 06:17:45.740612  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.059s	user 0.035s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26622,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:45.741200  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=2.188937
I20260812 06:17:45.764680  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.023s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6386,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:45.765247  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling MajorDeltaCompactionOp(7e9e9caaa7154a9492c957d61929619f): perf score=1.000000
I20260812 06:17:45.934831  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: MajorDeltaCompactionOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.169s	user 0.130s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":152,"lbm_read_time_us":11704,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30816,"lbm_writes_lt_1ms":543,"mutex_wait_us":35,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2500}
I20260812 06:17:45.935420  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=14.095187
I20260812 06:17:45.991981  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.056s	user 0.035s	sys 0.016s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":24742,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:45.992475  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling MajorDeltaCompactionOp(7e9e9caaa7154a9492c957d61929619f): perf score=1.000000
I20260812 06:17:46.148108  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: MajorDeltaCompactionOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.155s	user 0.088s	sys 0.064s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672156,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":160,"lbm_read_time_us":10907,"lbm_reads_lt_1ms":463,"lbm_write_time_us":26795,"lbm_writes_lt_1ms":443,"mutex_wait_us":59,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:46.148697  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=11.118625
I20260812 06:17:46.185645  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.037s	user 0.020s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15446,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:46.186326  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=2.188937
I20260812 06:17:46.198988  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4543,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:46.199559  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling MajorDeltaCompactionOp(7e9e9caaa7154a9492c957d61929619f): perf score=1.000000
I20260812 06:17:46.335851  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: MajorDeltaCompactionOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.136s	user 0.110s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":310,"lbm_read_time_us":10660,"lbm_reads_lt_1ms":468,"lbm_write_time_us":26203,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6272,"update_count":2000}
I20260812 06:17:46.336516  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=10.126437
I20260812 06:17:46.379603  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.043s	user 0.032s	sys 0.008s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":18812,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:46.380175  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=2.188937
I20260812 06:17:46.394902  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5223,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:46.395483  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling MajorDeltaCompactionOp(7e9e9caaa7154a9492c957d61929619f): perf score=1.000000
I20260812 06:17:46.532094  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: MajorDeltaCompactionOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.136s	user 0.096s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":478,"lbm_read_time_us":8260,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27342,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:17:46.532722  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=10.126437
I20260812 06:17:46.573385  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.040s	user 0.024s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16192,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:46.573999  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushMRSOp(7e9e9caaa7154a9492c957d61929619f): perf score=1.000000
I20260812 06:17:46.611330  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushMRSOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.037s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":209,"dirs.run_wall_time_us":1230,"drs_written":1,"lbm_read_time_us":104,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2151,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:46.612350  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling UndoDeltaBlockGCOp(7e9e9caaa7154a9492c957d61929619f): 463 bytes on disk
I20260812 06:17:46.613106  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: UndoDeltaBlockGCOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4}
I20260812 06:17:46.613688  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=3.181125
I20260812 06:17:46.627796  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.014s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4399,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:46.628314  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling LogGCOp(7e9e9caaa7154a9492c957d61929619f): free 120100330 bytes of WAL
I20260812 06:17:46.628535  8493 log_reader.cc:385] T 7e9e9caaa7154a9492c957d61929619f: removed 12 log segments from log reader
I20260812 06:17:46.628595  8493 log.cc:1079] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/7e9e9caaa7154a9492c957d61929619f/wal-000000014 (ops 66-70)
I20260812 06:17:46.628650  8493 log.cc:1079] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/7e9e9caaa7154a9492c957d61929619f/wal-000000015 (ops 71-75)
I20260812 06:17:46.628706  8493 log.cc:1079] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/7e9e9caaa7154a9492c957d61929619f/wal-000000016 (ops 76-80)
I20260812 06:17:46.628748  8493 log.cc:1079] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/7e9e9caaa7154a9492c957d61929619f/wal-000000017 (ops 81-84)
I20260812 06:17:46.628785  8493 log.cc:1079] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/7e9e9caaa7154a9492c957d61929619f/wal-000000018 (ops 85-89)
I20260812 06:17:46.628854  8493 log.cc:1079] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/7e9e9caaa7154a9492c957d61929619f/wal-000000019 (ops 90-94)
I20260812 06:17:46.628894  8493 log.cc:1079] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/7e9e9caaa7154a9492c957d61929619f/wal-000000020 (ops 95-99)
I20260812 06:17:46.628932  8493 log.cc:1079] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/7e9e9caaa7154a9492c957d61929619f/wal-000000021 (ops 100-104)
I20260812 06:17:46.628968  8493 log.cc:1079] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/7e9e9caaa7154a9492c957d61929619f/wal-000000022 (ops 105-108)
I20260812 06:17:46.629005  8493 log.cc:1079] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/7e9e9caaa7154a9492c957d61929619f/wal-000000023 (ops 109-113)
I20260812 06:17:46.629043  8493 log.cc:1079] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/7e9e9caaa7154a9492c957d61929619f/wal-000000024 (ops 114-118)
I20260812 06:17:46.629079  8493 log.cc:1079] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/7e9e9caaa7154a9492c957d61929619f/wal-000000025 (ops 119-122)
I20260812 06:17:46.657287  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: LogGCOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.029s	user 0.002s	sys 0.027s Metrics: {}
I20260812 06:17:46.657701  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=2.188937
I20260812 06:17:46.672577  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.015s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4239,"lbm_writes_lt_1ms":103,"mutex_wait_us":2,"reinsert_count":0,"update_count":500}
I20260812 06:17:46.673323  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=2.188937
I20260812 06:17:46.683534  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3951,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:46.683997  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling MajorDeltaCompactionOp(7e9e9caaa7154a9492c957d61929619f): perf score=1.000000
I20260812 06:17:46.904145  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: MajorDeltaCompactionOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.220s	user 0.138s	sys 0.062s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877330,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":969,"lbm_read_time_us":15297,"lbm_reads_lt_1ms":674,"lbm_write_time_us":41932,"lbm_writes_lt_1ms":643,"mutex_wait_us":336,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5632,"thread_start_us":78,"threads_started":1,"update_count":3000}
I20260812 06:17:46.904827  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=14.095187
I20260812 06:17:46.976559  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.069s	user 0.052s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":29128,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:46.977178  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=2.188937
I20260812 06:17:46.999094  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.022s	user 0.006s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7527,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:46.999569  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling MajorDeltaCompactionOp(7e9e9caaa7154a9492c957d61929619f): perf score=1.000000
I20260812 06:17:47.157392  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: MajorDeltaCompactionOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.158s	user 0.112s	sys 0.038s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1039,"lbm_read_time_us":11542,"lbm_reads_lt_1ms":568,"lbm_write_time_us":29011,"lbm_writes_lt_1ms":543,"mutex_wait_us":45,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2500}
I20260812 06:17:47.161309  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=14.095187
I20260812 06:17:47.215483  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.054s	user 0.034s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20639,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:47.216014  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=2.188937
I20260812 06:17:47.226991  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4305,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.227773  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling MajorDeltaCompactionOp(7e9e9caaa7154a9492c957d61929619f): perf score=1.000000
I20260812 06:17:47.416433  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: MajorDeltaCompactionOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.188s	user 0.128s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":381,"lbm_read_time_us":12572,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34077,"lbm_writes_lt_1ms":543,"mutex_wait_us":65,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":115712,"update_count":2500}
I20260812 06:17:47.417224  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=14.095187
I20260812 06:17:47.467761  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.050s	user 0.026s	sys 0.020s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":22267,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:47.468372  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling MajorDeltaCompactionOp(7e9e9caaa7154a9492c957d61929619f): perf score=1.000000
I20260812 06:17:47.627192  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: MajorDeltaCompactionOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.159s	user 0.094s	sys 0.060s 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":1217,"lbm_read_time_us":11012,"lbm_reads_lt_1ms":463,"lbm_write_time_us":27049,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:47.627812  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=14.095187
I20260812 06:17:47.685336  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.057s	user 0.027s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23427,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:47.685890  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=2.188937
I20260812 06:17:47.698334  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4612,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.698791  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling MajorDeltaCompactionOp(7e9e9caaa7154a9492c957d61929619f): perf score=1.000000
I20260812 06:17:47.893056  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: MajorDeltaCompactionOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.194s	user 0.110s	sys 0.077s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":378,"lbm_read_time_us":11722,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33606,"lbm_writes_lt_1ms":543,"mutex_wait_us":73,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":36864,"update_count":2500}
I20260812 06:17:47.897351  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=14.095187
I20260812 06:17:47.949405  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.052s	user 0.019s	sys 0.024s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19915,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:47.949981  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=2.188937
I20260812 06:17:47.962030  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.012s	user 0.001s	sys 0.010s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4511,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.962548  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling MajorDeltaCompactionOp(7e9e9caaa7154a9492c957d61929619f): perf score=1.000000
I20260812 06:17:48.129859  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: MajorDeltaCompactionOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.167s	user 0.114s	sys 0.047s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":863,"lbm_read_time_us":13191,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30479,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:48.130468  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=11.118625
I20260812 06:17:48.174733  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.044s	user 0.034s	sys 0.008s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":18328,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:48.175662  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=2.188937
I20260812 06:17:48.194557  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.019s	user 0.001s	sys 0.012s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5898,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:48.195164  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushMRSOp(7e9e9caaa7154a9492c957d61929619f): perf score=1.000000
I20260812 06:17:48.260661  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushMRSOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.065s	user 0.035s	sys 0.000s Metrics: {"bytes_written":1275445,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":235,"dirs.run_wall_time_us":1367,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1753,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:48.261593  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling LogGCOp(7e9e9caaa7154a9492c957d61929619f): free 121006613 bytes of WAL
I20260812 06:17:48.261855  8493 log_reader.cc:385] T 7e9e9caaa7154a9492c957d61929619f: removed 12 log segments from log reader
I20260812 06:17:48.261929  8493 log.cc:1079] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/7e9e9caaa7154a9492c957d61929619f/wal-000000026 (ops 123-127)
I20260812 06:17:48.261986  8493 log.cc:1079] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/7e9e9caaa7154a9492c957d61929619f/wal-000000027 (ops 128-132)
I20260812 06:17:48.262044  8493 log.cc:1079] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/7e9e9caaa7154a9492c957d61929619f/wal-000000028 (ops 133-137)
I20260812 06:17:48.262085  8493 log.cc:1079] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/7e9e9caaa7154a9492c957d61929619f/wal-000000029 (ops 138-142)
I20260812 06:17:48.262120  8493 log.cc:1079] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/7e9e9caaa7154a9492c957d61929619f/wal-000000030 (ops 143-147)
I20260812 06:17:48.262157  8493 log.cc:1079] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/7e9e9caaa7154a9492c957d61929619f/wal-000000031 (ops 148-152)
I20260812 06:17:48.262194  8493 log.cc:1079] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/7e9e9caaa7154a9492c957d61929619f/wal-000000032 (ops 153-157)
I20260812 06:17:48.262229  8493 log.cc:1079] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/7e9e9caaa7154a9492c957d61929619f/wal-000000033 (ops 158-162)
I20260812 06:17:48.262265  8493 log.cc:1079] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/7e9e9caaa7154a9492c957d61929619f/wal-000000034 (ops 163-166)
I20260812 06:17:48.262301  8493 log.cc:1079] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/7e9e9caaa7154a9492c957d61929619f/wal-000000035 (ops 167-171)
I20260812 06:17:48.262338  8493 log.cc:1079] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/7e9e9caaa7154a9492c957d61929619f/wal-000000036 (ops 172-176)
I20260812 06:17:48.262374  8493 log.cc:1079] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/7e9e9caaa7154a9492c957d61929619f/wal-000000037 (ops 177-181)
I20260812 06:17:48.292106  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: LogGCOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.030s	user 0.001s	sys 0.026s Metrics: {}
I20260812 06:17:48.292768  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling UndoDeltaBlockGCOp(7e9e9caaa7154a9492c957d61929619f): 482 bytes on disk
I20260812 06:17:48.293300  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: UndoDeltaBlockGCOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":89,"lbm_reads_lt_1ms":4}
I20260812 06:17:48.293897  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=7.149875
I20260812 06:17:48.332669  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.039s	user 0.017s	sys 0.018s Metrics: {"bytes_written":8615322,"delete_count":0,"lbm_write_time_us":10660,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:17:48.333266  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling LogGCOp(7e9e9caaa7154a9492c957d61929619f): free 12018006 bytes of WAL
I20260812 06:17:48.333524  8493 log_reader.cc:385] T 7e9e9caaa7154a9492c957d61929619f: removed 1 log segments from log reader
I20260812 06:17:48.333583  8493 log.cc:1079] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/7e9e9caaa7154a9492c957d61929619f/wal-000000038 (ops 182-186)
I20260812 06:17:48.336992  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: LogGCOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.004s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:48.337329  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=2.188937
I20260812 06:17:48.353930  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.016s	user 0.015s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6178,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:48.355643  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling MajorDeltaCompactionOp(7e9e9caaa7154a9492c957d61929619f): perf score=1.000000
I20260812 06:17:48.621254  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: MajorDeltaCompactionOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.265s	user 0.131s	sys 0.119s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979732,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":734,"lbm_read_time_us":16526,"lbm_reads_lt_1ms":774,"lbm_write_time_us":42386,"lbm_writes_lt_1ms":743,"mutex_wait_us":42,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":5120,"thread_start_us":87,"threads_started":1,"update_count":3500}
I20260812 06:17:48.622105  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f): perf score=18.063937
I20260812 06:17:48.678670  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: FlushDeltaMemStoresOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.056s	user 0.034s	sys 0.019s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":24914,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:48.679258  8576 maintenance_manager.cc:419] P ecfbfd452b5648d6ad748e61e99e1708: Scheduling MajorDeltaCompactionOp(7e9e9caaa7154a9492c957d61929619f): perf score=1.000000
I20260812 06:17:48.701063  8332 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.268s	user 1.928s	sys 0.139s
I20260812 06:17:48.773528  8332 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.072s	user 0.003s	sys 0.000s
I20260812 06:17:48.774235  8332 tablet_server.cc:179] TabletServer@127.8.35.1:0 shutting down...
I20260812 06:17:48.836874  8493 maintenance_manager.cc:643] P ecfbfd452b5648d6ad748e61e99e1708: MajorDeltaCompactionOp(7e9e9caaa7154a9492c957d61929619f) complete. Timing: real 0.157s	user 0.101s	sys 0.056s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24774571,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":512,"lbm_read_time_us":14459,"lbm_reads_lt_1ms":559,"lbm_write_time_us":26913,"lbm_writes_lt_1ms":543,"mutex_wait_us":66,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":23680,"update_count":2500}
I20260812 06:17:48.837868  8332 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:48.838287  8332 tablet_replica.cc:333] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708: stopping tablet replica
I20260812 06:17:48.838581  8332 raft_consensus.cc:2243] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:48.838867  8332 raft_consensus.cc:2272] T 7e9e9caaa7154a9492c957d61929619f P ecfbfd452b5648d6ad748e61e99e1708 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:48.847016  8332 tablet_server.cc:196] TabletServer@127.8.35.1:0 shutdown complete.
I20260812 06:17:48.884517  8332 master.cc:562] Master@127.8.35.62:46611 shutting down...
I20260812 06:17:48.888379  8332 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 0fef162c1ce04c01a06ffc201933a492 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:48.888583  8332 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 0fef162c1ce04c01a06ffc201933a492 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:48.888649  8332 tablet_replica.cc:333] T 00000000000000000000000000000000 P 0fef162c1ce04c01a06ffc201933a492: stopping tablet replica
I20260812 06:17:48.901360  8332 master.cc:584] Master@127.8.35.62:46611 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5847 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:49.014096  8332 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.8.35.62:42673
I20260812 06:17:49.014706  8332 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:49.017045  8627 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:17:49.017109  8332 server_base.cc:1061] running on GCE node
W20260812 06:17:49.017153  8626 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:17:49.017158  8629 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:17:49.017448  8332 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:49.017514  8332 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:17:49.017540  8332 hybrid_clock.cc:648] HybridClock initialized: now 1786515469017539 us; error 0 us; skew 500 ppm
I20260812 06:17:49.018340  8332 webserver.cc:533] Webserver started at http://127.8.35.62:39923/ using document root <none> and password file <none>
I20260812 06:17:49.018538  8332 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:49.018610  8332 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:49.018690  8332 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:49.019112  8332 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/master-0-root/instance:
uuid: "89f9629d339f48b6876069c4023420ba"
format_stamp: "Formatted at 2026-08-12 06:17:49 on dist-test-slave-zh2d"
I20260812 06:17:49.020670  8332 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:49.021749  8637 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:17:49.022022  8332 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:49.022113  8332 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/master-0-root
uuid: "89f9629d339f48b6876069c4023420ba"
format_stamp: "Formatted at 2026-08-12 06:17:49 on dist-test-slave-zh2d"
I20260812 06:17:49.022203  8332 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-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:17:49.028285  8332 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:49.028643  8332 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:49.033628  8332 rpc_server.cc:307] RPC server started. Bound to: 127.8.35.62:42673
I20260812 06:17:49.037810  8716 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.35.62:42673 every 8 connection(s)
I20260812 06:17:49.038362  8717 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:17:49.040122  8717 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 89f9629d339f48b6876069c4023420ba: Bootstrap starting.
I20260812 06:17:49.040928  8717 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 89f9629d339f48b6876069c4023420ba: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:49.041877  8717 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 89f9629d339f48b6876069c4023420ba: No bootstrap required, opened a new log
I20260812 06:17:49.042236  8717 raft_consensus.cc:359] T 00000000000000000000000000000000 P 89f9629d339f48b6876069c4023420ba [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "89f9629d339f48b6876069c4023420ba" member_type: VOTER }
I20260812 06:17:49.042343  8717 raft_consensus.cc:385] T 00000000000000000000000000000000 P 89f9629d339f48b6876069c4023420ba [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:49.042366  8717 raft_consensus.cc:740] T 00000000000000000000000000000000 P 89f9629d339f48b6876069c4023420ba [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 89f9629d339f48b6876069c4023420ba, State: Initialized, Role: FOLLOWER
I20260812 06:17:49.042496  8717 consensus_queue.cc:260] T 00000000000000000000000000000000 P 89f9629d339f48b6876069c4023420ba [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: "89f9629d339f48b6876069c4023420ba" member_type: VOTER }
I20260812 06:17:49.042559  8717 raft_consensus.cc:399] T 00000000000000000000000000000000 P 89f9629d339f48b6876069c4023420ba [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:49.042582  8717 raft_consensus.cc:493] T 00000000000000000000000000000000 P 89f9629d339f48b6876069c4023420ba [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:49.042616  8717 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 89f9629d339f48b6876069c4023420ba [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:49.043237  8717 raft_consensus.cc:515] T 00000000000000000000000000000000 P 89f9629d339f48b6876069c4023420ba [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "89f9629d339f48b6876069c4023420ba" member_type: VOTER }
I20260812 06:17:49.043349  8717 leader_election.cc:304] T 00000000000000000000000000000000 P 89f9629d339f48b6876069c4023420ba [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: 89f9629d339f48b6876069c4023420ba; no voters: 
I20260812 06:17:49.043496  8717 leader_election.cc:290] T 00000000000000000000000000000000 P 89f9629d339f48b6876069c4023420ba [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:49.043627  8723 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 89f9629d339f48b6876069c4023420ba [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:49.043835  8723 raft_consensus.cc:697] T 00000000000000000000000000000000 P 89f9629d339f48b6876069c4023420ba [term 1 LEADER]: Becoming Leader. State: Replica: 89f9629d339f48b6876069c4023420ba, State: Running, Role: LEADER
I20260812 06:17:49.044000  8717 sys_catalog.cc:565] T 00000000000000000000000000000000 P 89f9629d339f48b6876069c4023420ba [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:49.043994  8723 consensus_queue.cc:237] T 00000000000000000000000000000000 P 89f9629d339f48b6876069c4023420ba [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: "89f9629d339f48b6876069c4023420ba" member_type: VOTER }
I20260812 06:17:49.044622  8727 sys_catalog.cc:455] T 00000000000000000000000000000000 P 89f9629d339f48b6876069c4023420ba [sys.catalog]: SysCatalogTable state changed. Reason: New leader 89f9629d339f48b6876069c4023420ba. Latest consensus state: current_term: 1 leader_uuid: "89f9629d339f48b6876069c4023420ba" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "89f9629d339f48b6876069c4023420ba" member_type: VOTER } }
I20260812 06:17:49.044785  8727 sys_catalog.cc:458] T 00000000000000000000000000000000 P 89f9629d339f48b6876069c4023420ba [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:49.045002  8725 sys_catalog.cc:455] T 00000000000000000000000000000000 P 89f9629d339f48b6876069c4023420ba [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "89f9629d339f48b6876069c4023420ba" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "89f9629d339f48b6876069c4023420ba" member_type: VOTER } }
I20260812 06:17:49.045104  8725 sys_catalog.cc:458] T 00000000000000000000000000000000 P 89f9629d339f48b6876069c4023420ba [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:49.045476  8739 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:49.046360  8739 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:49.046612  8332 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:49.048207  8739 catalog_manager.cc:1383] Generated new cluster ID: 508aaf0bd0004d91a02b6854c2ed6e4a
I20260812 06:17:49.048269  8739 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:49.057993  8739 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:49.058545  8739 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:49.079322  8739 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 89f9629d339f48b6876069c4023420ba: Generated new TSK 0
I20260812 06:17:49.079571  8739 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:49.111431  8332 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:49.113664  8750 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:17:49.113682  8754 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:17:49.113801  8752 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:17:49.113906  8332 server_base.cc:1061] running on GCE node
I20260812 06:17:49.114173  8332 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:49.114235  8332 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:17:49.114269  8332 hybrid_clock.cc:648] HybridClock initialized: now 1786515469114268 us; error 0 us; skew 500 ppm
I20260812 06:17:49.115175  8332 webserver.cc:533] Webserver started at http://127.8.35.1:42265/ using document root <none> and password file <none>
I20260812 06:17:49.115353  8332 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:49.115422  8332 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:49.115521  8332 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:49.115931  8332 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/instance:
uuid: "f25b943c8d604177842fa0df13c490c9"
format_stamp: "Formatted at 2026-08-12 06:17:49 on dist-test-slave-zh2d"
I20260812 06:17:49.117607  8332 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:49.118548  8765 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:17:49.118813  8332 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:49.118902  8332 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root
uuid: "f25b943c8d604177842fa0df13c490c9"
format_stamp: "Formatted at 2026-08-12 06:17:49 on dist-test-slave-zh2d"
I20260812 06:17:49.118988  8332 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-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:17:49.124975  8332 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:49.125303  8332 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:49.125653  8332 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:49.126099  8332 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:49.126160  8332 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:49.126217  8332 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:49.126256  8332 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:49.130946  8332 rpc_server.cc:307] RPC server started. Bound to: 127.8.35.1:36361
I20260812 06:17:49.131567  8863 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.35.1:36361 every 8 connection(s)
I20260812 06:17:49.142072  8865 heartbeater.cc:344] Connected to a master server at 127.8.35.62:42673
I20260812 06:17:49.142186  8865 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:49.142387  8865 heartbeater.cc:507] Master 127.8.35.62:42673 requested a full tablet report, sending...
I20260812 06:17:49.143081  8662 ts_manager.cc:194] Registered new tserver with Master: f25b943c8d604177842fa0df13c490c9 (127.8.35.1:36361)
I20260812 06:17:49.143769  8662 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:52166
I20260812 06:17:49.143900  8332 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012196177s
I20260812 06:17:49.151661  8662 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:52168:
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:17:49.160183  8806 tablet_service.cc:1511] Processing CreateTablet for tablet a6ae79efcc49488886d6f8a4f594a8b8 (DEFAULT_TABLE table=heavy-update-compaction-test [id=9802e88645c64608b57fb52cc0768613]), partition=
I20260812 06:17:49.160478  8806 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet a6ae79efcc49488886d6f8a4f594a8b8. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:49.162431  8883 tablet_bootstrap.cc:492] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Bootstrap starting.
I20260812 06:17:49.163278  8883 tablet_bootstrap.cc:654] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:49.164276  8883 tablet_bootstrap.cc:492] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: No bootstrap required, opened a new log
I20260812 06:17:49.164391  8883 ts_tablet_manager.cc:1403] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:17:49.164786  8883 raft_consensus.cc:359] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f25b943c8d604177842fa0df13c490c9" member_type: VOTER last_known_addr { host: "127.8.35.1" port: 36361 } }
I20260812 06:17:49.164940  8883 raft_consensus.cc:385] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:49.164991  8883 raft_consensus.cc:740] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f25b943c8d604177842fa0df13c490c9, State: Initialized, Role: FOLLOWER
I20260812 06:17:49.165134  8883 consensus_queue.cc:260] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9 [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: "f25b943c8d604177842fa0df13c490c9" member_type: VOTER last_known_addr { host: "127.8.35.1" port: 36361 } }
I20260812 06:17:49.165237  8883 raft_consensus.cc:399] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:49.165280  8883 raft_consensus.cc:493] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:49.165346  8883 raft_consensus.cc:3060] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:49.166203  8883 raft_consensus.cc:515] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f25b943c8d604177842fa0df13c490c9" member_type: VOTER last_known_addr { host: "127.8.35.1" port: 36361 } }
I20260812 06:17:49.166359  8883 leader_election.cc:304] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9 [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: f25b943c8d604177842fa0df13c490c9; no voters: 
I20260812 06:17:49.166590  8883 leader_election.cc:290] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:49.166746  8886 raft_consensus.cc:2804] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:49.166922  8883 ts_tablet_manager.cc:1434] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:17:49.166978  8886 raft_consensus.cc:697] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9 [term 1 LEADER]: Becoming Leader. State: Replica: f25b943c8d604177842fa0df13c490c9, State: Running, Role: LEADER
I20260812 06:17:49.166939  8865 heartbeater.cc:499] Master 127.8.35.62:42673 was elected leader, sending a full tablet report...
I20260812 06:17:49.167321  8886 consensus_queue.cc:237] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9 [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: "f25b943c8d604177842fa0df13c490c9" member_type: VOTER last_known_addr { host: "127.8.35.1" port: 36361 } }
I20260812 06:17:49.168692  8662 catalog_manager.cc:5719] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9 reported cstate change: term changed from 0 to 1, leader changed from <none> to f25b943c8d604177842fa0df13c490c9 (127.8.35.1). New cstate: current_term: 1 leader_uuid: "f25b943c8d604177842fa0df13c490c9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f25b943c8d604177842fa0df13c490c9" member_type: VOTER last_known_addr { host: "127.8.35.1" port: 36361 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:49.231323  8332 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.015s	sys 0.008s
I20260812 06:17:49.382153  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushMRSOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=19.054940
I20260812 06:17:49.559466  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushMRSOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.177s	user 0.097s	sys 0.073s Metrics: {"bytes_written":12307492,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":81,"dirs.run_cpu_time_us":190,"dirs.run_wall_time_us":756,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41182,"lbm_writes_lt_1ms":757,"mutex_wait_us":2,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":4480,"update_count":1500}
I20260812 06:17:49.560161  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling LogGCOp(a6ae79efcc49488886d6f8a4f594a8b8): free 20290830 bytes of WAL
I20260812 06:17:49.560407  8770 log_reader.cc:385] T a6ae79efcc49488886d6f8a4f594a8b8: removed 2 log segments from log reader
I20260812 06:17:49.560460  8770 log.cc:1079] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/a6ae79efcc49488886d6f8a4f594a8b8/wal-000000001 (ops 1-6)
I20260812 06:17:49.560491  8770 log.cc:1079] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/a6ae79efcc49488886d6f8a4f594a8b8/wal-000000002 (ops 7-10)
I20260812 06:17:49.564765  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: LogGCOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:49.565182  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=2.188937
I20260812 06:17:49.577257  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.012s	user 0.005s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4748,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:49.579855  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling UndoDeltaBlockGCOp(a6ae79efcc49488886d6f8a4f594a8b8): 16411395 bytes on disk
I20260812 06:17:49.580492  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: UndoDeltaBlockGCOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":96,"lbm_reads_lt_1ms":4}
I20260812 06:17:49.581116  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling MajorDeltaCompactionOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=1.000000
I20260812 06:17:49.779238  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: MajorDeltaCompactionOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.198s	user 0.129s	sys 0.068s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":307,"lbm_read_time_us":11625,"lbm_reads_lt_1ms":464,"lbm_write_time_us":33689,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4480,"thread_start_us":461,"threads_started":5,"update_count":2000}
I20260812 06:17:49.779877  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=10.126437
I20260812 06:17:49.822531  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.042s	user 0.023s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17435,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:49.823199  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=2.188937
I20260812 06:17:49.843375  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.020s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7137,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:49.844234  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling MajorDeltaCompactionOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=1.000000
I20260812 06:17:50.025908  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: MajorDeltaCompactionOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.181s	user 0.148s	sys 0.026s 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":1600,"lbm_read_time_us":13659,"lbm_reads_lt_1ms":472,"lbm_write_time_us":34328,"lbm_writes_lt_1ms":443,"mutex_wait_us":439,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":2000}
I20260812 06:17:50.026554  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=10.126437
I20260812 06:17:50.064430  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.038s	user 0.013s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15508,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:50.065097  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling MajorDeltaCompactionOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=1.000000
I20260812 06:17:50.183024  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: MajorDeltaCompactionOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.118s	user 0.096s	sys 0.022s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569747,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":182,"lbm_read_time_us":8412,"lbm_reads_lt_1ms":367,"lbm_write_time_us":24005,"lbm_writes_lt_1ms":343,"mutex_wait_us":41,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":1500}
I20260812 06:17:50.183657  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=10.126437
I20260812 06:17:50.235865  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.052s	user 0.033s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":20091,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:50.236438  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling MajorDeltaCompactionOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=1.000000
I20260812 06:17:50.364913  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: MajorDeltaCompactionOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.128s	user 0.081s	sys 0.047s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569747,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":530,"lbm_read_time_us":10538,"lbm_reads_lt_1ms":363,"lbm_write_time_us":19640,"lbm_writes_lt_1ms":343,"mutex_wait_us":31,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":1500}
I20260812 06:17:50.365689  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=10.126437
I20260812 06:17:50.405289  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.039s	user 0.015s	sys 0.024s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17716,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:50.405805  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=2.188937
I20260812 06:17:50.417474  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4318,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:50.418097  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling MajorDeltaCompactionOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=1.000000
I20260812 06:17:50.554828  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: MajorDeltaCompactionOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.137s	user 0.100s	sys 0.036s 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":256,"lbm_read_time_us":9547,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27175,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2000}
I20260812 06:17:50.555573  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=10.126437
I20260812 06:17:50.602298  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.047s	user 0.021s	sys 0.015s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16754,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:50.602777  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=2.188937
I20260812 06:17:50.613794  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4438,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:50.614269  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling MajorDeltaCompactionOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=1.000000
I20260812 06:17:50.747406  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: MajorDeltaCompactionOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.133s	user 0.086s	sys 0.046s 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":433,"lbm_read_time_us":10980,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25955,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:17:50.748144  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=10.126437
I20260812 06:17:50.803334  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.055s	user 0.025s	sys 0.022s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16628,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:50.803911  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=2.188937
I20260812 06:17:50.821245  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.017s	user 0.013s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6464,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:50.821868  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling MajorDeltaCompactionOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=1.000000
I20260812 06:17:50.986536  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: MajorDeltaCompactionOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.164s	user 0.116s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":206,"lbm_read_time_us":12740,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28112,"lbm_writes_lt_1ms":443,"mutex_wait_us":51,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16256,"update_count":2000}
I20260812 06:17:50.987344  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=10.126437
I20260812 06:17:51.042039  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.055s	user 0.027s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19483,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:51.042574  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=2.188937
I20260812 06:17:51.054801  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4484,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:51.055454  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushMRSOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=1.000000
I20260812 06:17:51.093750  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushMRSOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.038s	user 0.031s	sys 0.004s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":225,"dirs.run_wall_time_us":1337,"drs_written":1,"lbm_read_time_us":83,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1841,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:51.094411  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling LogGCOp(a6ae79efcc49488886d6f8a4f594a8b8): free 116849463 bytes of WAL
I20260812 06:17:51.094645  8770 log_reader.cc:385] T a6ae79efcc49488886d6f8a4f594a8b8: removed 12 log segments from log reader
I20260812 06:17:51.094704  8770 log.cc:1079] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/a6ae79efcc49488886d6f8a4f594a8b8/wal-000000003 (ops 11-15)
I20260812 06:17:51.094758  8770 log.cc:1079] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/a6ae79efcc49488886d6f8a4f594a8b8/wal-000000004 (ops 16-20)
I20260812 06:17:51.094825  8770 log.cc:1079] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/a6ae79efcc49488886d6f8a4f594a8b8/wal-000000005 (ops 21-24)
I20260812 06:17:51.094864  8770 log.cc:1079] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/a6ae79efcc49488886d6f8a4f594a8b8/wal-000000006 (ops 25-29)
I20260812 06:17:51.094901  8770 log.cc:1079] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/a6ae79efcc49488886d6f8a4f594a8b8/wal-000000007 (ops 30-34)
I20260812 06:17:51.094939  8770 log.cc:1079] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/a6ae79efcc49488886d6f8a4f594a8b8/wal-000000008 (ops 35-38)
I20260812 06:17:51.094975  8770 log.cc:1079] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/a6ae79efcc49488886d6f8a4f594a8b8/wal-000000009 (ops 39-43)
I20260812 06:17:51.095013  8770 log.cc:1079] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/a6ae79efcc49488886d6f8a4f594a8b8/wal-000000010 (ops 44-48)
I20260812 06:17:51.095049  8770 log.cc:1079] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/a6ae79efcc49488886d6f8a4f594a8b8/wal-000000011 (ops 49-53)
I20260812 06:17:51.095086  8770 log.cc:1079] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/a6ae79efcc49488886d6f8a4f594a8b8/wal-000000012 (ops 54-58)
I20260812 06:17:51.095124  8770 log.cc:1079] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/a6ae79efcc49488886d6f8a4f594a8b8/wal-000000013 (ops 59-62)
I20260812 06:17:51.095158  8770 log.cc:1079] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/a6ae79efcc49488886d6f8a4f594a8b8/wal-000000014 (ops 63-67)
I20260812 06:17:51.123524  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: LogGCOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.029s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:51.124025  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=3.181125
I20260812 06:17:51.148862  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.025s	user 0.009s	sys 0.011s Metrics: {"bytes_written":5251342,"delete_count":0,"lbm_write_time_us":5984,"lbm_writes_lt_1ms":131,"mutex_wait_us":134,"reinsert_count":0,"update_count":640}
I20260812 06:17:51.149492  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling UndoDeltaBlockGCOp(a6ae79efcc49488886d6f8a4f594a8b8): 471 bytes on disk
I20260812 06:17:51.149963  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: UndoDeltaBlockGCOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:17:51.150473  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=1.196750
I20260812 06:17:51.159581  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":2953955,"delete_count":0,"lbm_write_time_us":3283,"lbm_writes_lt_1ms":75,"reinsert_count":0,"update_count":360}
I20260812 06:17:51.159981  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling MajorDeltaCompactionOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=1.000000
I20260812 06:17:51.386129  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: MajorDeltaCompactionOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.226s	user 0.154s	sys 0.071s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":695,"lbm_read_time_us":16445,"lbm_reads_lt_1ms":674,"lbm_write_time_us":38703,"lbm_writes_lt_1ms":643,"mutex_wait_us":650,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3712,"thread_start_us":86,"threads_started":1,"update_count":3000}
I20260812 06:17:51.386880  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=14.095187
I20260812 06:17:51.449004  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.062s	user 0.023s	sys 0.039s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21684,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:51.449765  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=2.188937
I20260812 06:17:51.463138  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.013s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4805,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:51.463915  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling MajorDeltaCompactionOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=1.000000
I20260812 06:17:51.685674  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: MajorDeltaCompactionOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.222s	user 0.134s	sys 0.087s 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":957,"lbm_read_time_us":16589,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34279,"lbm_writes_lt_1ms":543,"mutex_wait_us":72,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":22656,"update_count":2500}
I20260812 06:17:51.686421  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=14.095187
I20260812 06:17:51.744680  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.058s	user 0.030s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26303,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:51.745285  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=2.188937
I20260812 06:17:51.771397  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.026s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5639,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:51.771916  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling MajorDeltaCompactionOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=1.000000
I20260812 06:17:51.964468  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: MajorDeltaCompactionOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.192s	user 0.136s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1072,"lbm_read_time_us":14223,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31141,"lbm_writes_lt_1ms":543,"mutex_wait_us":319,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:17:51.965148  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=14.095187
I20260812 06:17:52.021019  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.056s	user 0.031s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23706,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:52.021515  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=2.188937
I20260812 06:17:52.033788  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.012s	user 0.008s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4476,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:52.034255  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling MajorDeltaCompactionOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=1.000000
I20260812 06:17:52.251163  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: MajorDeltaCompactionOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.217s	user 0.135s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1230,"lbm_read_time_us":12475,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35996,"lbm_writes_lt_1ms":543,"mutex_wait_us":443,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5504,"update_count":2500}
I20260812 06:17:52.251842  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=14.095187
I20260812 06:17:52.303797  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.052s	user 0.030s	sys 0.013s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20490,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:52.304397  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=2.188937
I20260812 06:17:52.316035  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4316,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:52.316859  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling MajorDeltaCompactionOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=1.000000
I20260812 06:17:52.496775  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: MajorDeltaCompactionOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.180s	user 0.142s	sys 0.029s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1078,"lbm_read_time_us":11868,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33279,"lbm_writes_lt_1ms":543,"mutex_wait_us":330,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9856,"update_count":2500}
I20260812 06:17:52.497437  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=14.095187
I20260812 06:17:52.549347  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.052s	user 0.032s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26212,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:52.549822  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=2.188937
I20260812 06:17:52.563429  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4591,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:52.563925  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling MajorDeltaCompactionOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=1.000000
I20260812 06:17:52.728605  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: MajorDeltaCompactionOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.165s	user 0.140s	sys 0.024s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1471,"lbm_read_time_us":13292,"lbm_reads_lt_1ms":568,"lbm_write_time_us":35372,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8576,"update_count":2500}
I20260812 06:17:52.729394  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=10.126437
I20260812 06:17:52.764642  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.035s	user 0.017s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15727,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:52.765383  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=2.188937
I20260812 06:17:52.782040  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.016s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6590,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:52.782512  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushMRSOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=1.000000
I20260812 06:17:52.811513  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushMRSOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.029s	user 0.024s	sys 0.003s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":182,"dirs.run_wall_time_us":1263,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2011,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:52.812247  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling LogGCOp(a6ae79efcc49488886d6f8a4f594a8b8): free 129320570 bytes of WAL
I20260812 06:17:52.812542  8770 log_reader.cc:385] T a6ae79efcc49488886d6f8a4f594a8b8: removed 13 log segments from log reader
I20260812 06:17:52.812602  8770 log.cc:1079] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/a6ae79efcc49488886d6f8a4f594a8b8/wal-000000015 (ops 68-72)
I20260812 06:17:52.812644  8770 log.cc:1079] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/a6ae79efcc49488886d6f8a4f594a8b8/wal-000000016 (ops 73-76)
I20260812 06:17:52.812680  8770 log.cc:1079] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/a6ae79efcc49488886d6f8a4f594a8b8/wal-000000017 (ops 77-81)
I20260812 06:17:52.812711  8770 log.cc:1079] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/a6ae79efcc49488886d6f8a4f594a8b8/wal-000000018 (ops 82-86)
I20260812 06:17:52.812738  8770 log.cc:1079] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/a6ae79efcc49488886d6f8a4f594a8b8/wal-000000019 (ops 87-91)
I20260812 06:17:52.812762  8770 log.cc:1079] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/a6ae79efcc49488886d6f8a4f594a8b8/wal-000000020 (ops 92-96)
I20260812 06:17:52.812788  8770 log.cc:1079] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/a6ae79efcc49488886d6f8a4f594a8b8/wal-000000021 (ops 97-100)
I20260812 06:17:52.812824  8770 log.cc:1079] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/a6ae79efcc49488886d6f8a4f594a8b8/wal-000000022 (ops 101-105)
I20260812 06:17:52.812894  8770 log.cc:1079] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/a6ae79efcc49488886d6f8a4f594a8b8/wal-000000023 (ops 106-110)
I20260812 06:17:52.812918  8770 log.cc:1079] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/a6ae79efcc49488886d6f8a4f594a8b8/wal-000000024 (ops 111-115)
I20260812 06:17:52.812948  8770 log.cc:1079] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/a6ae79efcc49488886d6f8a4f594a8b8/wal-000000025 (ops 116-120)
I20260812 06:17:52.812979  8770 log.cc:1079] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/a6ae79efcc49488886d6f8a4f594a8b8/wal-000000026 (ops 121-125)
I20260812 06:17:52.813014  8770 log.cc:1079] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/a6ae79efcc49488886d6f8a4f594a8b8/wal-000000027 (ops 126-130)
I20260812 06:17:52.842404  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: LogGCOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.030s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:17:52.842833  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling UndoDeltaBlockGCOp(a6ae79efcc49488886d6f8a4f594a8b8): 483 bytes on disk
I20260812 06:17:52.843472  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: UndoDeltaBlockGCOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:17:52.844106  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=4.173312
I20260812 06:17:52.864490  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.020s	user 0.014s	sys 0.004s Metrics: {"bytes_written":6194894,"delete_count":0,"lbm_write_time_us":8413,"lbm_writes_lt_1ms":154,"reinsert_count":0,"update_count":755}
I20260812 06:17:52.865100  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling LogGCOp(a6ae79efcc49488886d6f8a4f594a8b8): free 11564893 bytes of WAL
I20260812 06:17:52.865357  8770 log_reader.cc:385] T a6ae79efcc49488886d6f8a4f594a8b8: removed 1 log segments from log reader
I20260812 06:17:52.865427  8770 log.cc:1079] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/a6ae79efcc49488886d6f8a4f594a8b8/wal-000000028 (ops 131-134)
I20260812 06:17:52.869122  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: LogGCOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.004s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:17:52.869537  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=1.000000
I20260812 06:17:52.880415  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":2010377,"delete_count":0,"lbm_write_time_us":3164,"lbm_writes_lt_1ms":52,"reinsert_count":0,"update_count":245}
I20260812 06:17:52.881029  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling MajorDeltaCompactionOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=1.000000
I20260812 06:17:53.056951  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: MajorDeltaCompactionOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.176s	user 0.090s	sys 0.085s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877287,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":40,"lbm_read_time_us":12374,"lbm_reads_lt_1ms":666,"lbm_write_time_us":37092,"lbm_writes_lt_1ms":643,"mutex_wait_us":25,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3072,"thread_start_us":111,"threads_started":1,"update_count":3000}
I20260812 06:17:53.057663  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=15.087375
I20260812 06:17:53.112172  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.054s	user 0.021s	sys 0.030s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":24085,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:53.112792  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=2.188937
I20260812 06:17:53.129717  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.016s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5474,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:53.130236  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling MajorDeltaCompactionOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=1.000000
I20260812 06:17:53.302688  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: MajorDeltaCompactionOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.172s	user 0.130s	sys 0.033s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774676,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":210,"lbm_read_time_us":12154,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30705,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2500}
I20260812 06:17:53.303436  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=14.095187
I20260812 06:17:53.348136  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.044s	user 0.022s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19808,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:53.348706  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling MajorDeltaCompactionOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=1.000000
I20260812 06:17:53.508128  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: MajorDeltaCompactionOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.159s	user 0.116s	sys 0.040s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672159,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1218,"lbm_read_time_us":11636,"lbm_reads_lt_1ms":467,"lbm_write_time_us":26588,"lbm_writes_lt_1ms":443,"mutex_wait_us":709,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10240,"update_count":2000}
I20260812 06:17:53.508881  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=11.118625
I20260812 06:17:53.552888  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.044s	user 0.013s	sys 0.024s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18952,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:53.553645  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=2.188937
I20260812 06:17:53.571898  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.018s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6844,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:53.572389  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=2.188937
I20260812 06:17:53.582506  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3967,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:53.582952  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling MajorDeltaCompactionOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=1.000000
I20260812 06:17:53.782457  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: MajorDeltaCompactionOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.199s	user 0.117s	sys 0.078s 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":184,"lbm_read_time_us":13026,"lbm_reads_lt_1ms":573,"lbm_write_time_us":35377,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":21120,"update_count":2500}
I20260812 06:17:53.783398  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=14.095187
I20260812 06:17:53.841979  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.058s	user 0.029s	sys 0.024s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":24177,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:53.842554  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=2.188937
I20260812 06:17:53.854655  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4535,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:53.855309  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling MajorDeltaCompactionOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=1.000000
I20260812 06:17:54.037904  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: MajorDeltaCompactionOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.182s	user 0.138s	sys 0.031s 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":653,"lbm_read_time_us":13378,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33634,"lbm_writes_lt_1ms":543,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":89984,"update_count":2500}
I20260812 06:17:54.038444  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=14.095187
I20260812 06:17:54.092674  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.054s	user 0.021s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21720,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:54.093238  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=2.188937
I20260812 06:17:54.105129  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.012s	user 0.008s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4423,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:54.105643  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling MajorDeltaCompactionOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=1.000000
I20260812 06:17:54.278846  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: MajorDeltaCompactionOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.173s	user 0.137s	sys 0.027s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":61,"lbm_read_time_us":11851,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33764,"lbm_writes_lt_1ms":543,"mutex_wait_us":79,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:54.281852  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=14.095187
I20260812 06:17:54.333530  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.051s	user 0.031s	sys 0.020s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":22301,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:54.334137  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=2.188937
I20260812 06:17:54.351220  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.017s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6729,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:54.351821  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushMRSOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=1.000000
I20260812 06:17:54.380767  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushMRSOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.029s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":266,"dirs.run_wall_time_us":1481,"drs_written":1,"lbm_read_time_us":86,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1957,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31,"spinlock_wait_cycles":1920}
I20260812 06:17:54.381502  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling LogGCOp(a6ae79efcc49488886d6f8a4f594a8b8): free 120553644 bytes of WAL
I20260812 06:17:54.381733  8770 log_reader.cc:385] T a6ae79efcc49488886d6f8a4f594a8b8: removed 12 log segments from log reader
I20260812 06:17:54.381798  8770 log.cc:1079] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/a6ae79efcc49488886d6f8a4f594a8b8/wal-000000029 (ops 135-139)
I20260812 06:17:54.381848  8770 log.cc:1079] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/a6ae79efcc49488886d6f8a4f594a8b8/wal-000000030 (ops 140-144)
I20260812 06:17:54.381916  8770 log.cc:1079] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/a6ae79efcc49488886d6f8a4f594a8b8/wal-000000031 (ops 145-149)
I20260812 06:17:54.381959  8770 log.cc:1079] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/a6ae79efcc49488886d6f8a4f594a8b8/wal-000000032 (ops 150-154)
I20260812 06:17:54.382002  8770 log.cc:1079] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/a6ae79efcc49488886d6f8a4f594a8b8/wal-000000033 (ops 155-158)
I20260812 06:17:54.382041  8770 log.cc:1079] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/a6ae79efcc49488886d6f8a4f594a8b8/wal-000000034 (ops 159-163)
I20260812 06:17:54.382082  8770 log.cc:1079] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/a6ae79efcc49488886d6f8a4f594a8b8/wal-000000035 (ops 164-168)
I20260812 06:17:54.382122  8770 log.cc:1079] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/a6ae79efcc49488886d6f8a4f594a8b8/wal-000000036 (ops 169-173)
I20260812 06:17:54.382162  8770 log.cc:1079] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/a6ae79efcc49488886d6f8a4f594a8b8/wal-000000037 (ops 174-178)
I20260812 06:17:54.382202  8770 log.cc:1079] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/a6ae79efcc49488886d6f8a4f594a8b8/wal-000000038 (ops 179-183)
I20260812 06:17:54.382242  8770 log.cc:1079] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/a6ae79efcc49488886d6f8a4f594a8b8/wal-000000039 (ops 184-188)
I20260812 06:17:54.382280  8770 log.cc:1079] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: Deleting log segment in path: /tmp/dist-test-task2Uq6zR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515463140226-8332-0/minicluster-data/ts-0-root/wals/a6ae79efcc49488886d6f8a4f594a8b8/wal-000000040 (ops 189-192)
I20260812 06:17:54.412227  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: LogGCOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.031s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:17:54.412750  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=3.181125
I20260812 06:17:54.431217  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.018s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7554,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:54.431674  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling UndoDeltaBlockGCOp(a6ae79efcc49488886d6f8a4f594a8b8): 482 bytes on disk
I20260812 06:17:54.432071  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: UndoDeltaBlockGCOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:17:54.432567  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=2.188937
I20260812 06:17:54.443603  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: FlushDeltaMemStoresOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3971,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:54.444334  8866 maintenance_manager.cc:419] P f25b943c8d604177842fa0df13c490c9: Scheduling MajorDeltaCompactionOp(a6ae79efcc49488886d6f8a4f594a8b8): perf score=1.000000
I20260812 06:17:54.540299  8332 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.309s	user 2.038s	sys 0.129s
I20260812 06:17:54.637928  8332 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.097s	user 0.002s	sys 0.000s
I20260812 06:17:54.638478  8332 tablet_server.cc:179] TabletServer@127.8.35.1:0 shutting down...
I20260812 06:17:54.685241  8770 maintenance_manager.cc:643] P f25b943c8d604177842fa0df13c490c9: MajorDeltaCompactionOp(a6ae79efcc49488886d6f8a4f594a8b8) complete. Timing: real 0.241s	user 0.141s	sys 0.094s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979739,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":597,"lbm_read_time_us":16378,"lbm_reads_lt_1ms":770,"lbm_write_time_us":37989,"lbm_writes_lt_1ms":743,"mutex_wait_us":59,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":9344,"thread_start_us":87,"threads_started":1,"update_count":3500}
I20260812 06:17:54.686039  8332 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:54.686280  8332 tablet_replica.cc:333] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9: stopping tablet replica
I20260812 06:17:54.686441  8332 raft_consensus.cc:2243] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:54.686676  8332 raft_consensus.cc:2272] T a6ae79efcc49488886d6f8a4f594a8b8 P f25b943c8d604177842fa0df13c490c9 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:54.692586  8332 tablet_server.cc:196] TabletServer@127.8.35.1:0 shutdown complete.
I20260812 06:17:54.743819  8332 master.cc:562] Master@127.8.35.62:42673 shutting down...
I20260812 06:17:54.747663  8332 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 89f9629d339f48b6876069c4023420ba [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:54.747902  8332 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 89f9629d339f48b6876069c4023420ba [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:54.748004  8332 tablet_replica.cc:333] T 00000000000000000000000000000000 P 89f9629d339f48b6876069c4023420ba: stopping tablet replica
I20260812 06:17:54.760710  8332 master.cc:584] Master@127.8.35.62:42673 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5855 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11703 ms total)

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