[==========] 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:23.836199 29432 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.28.190.62:34367
I20260812 06:17:23.837118 29432 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:23.837646 29432 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:23.844319 29437 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:23.844374 29432 server_base.cc:1061] running on GCE node
W20260812 06:17:23.844305 29439 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:23.844580 29441 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:23.845158 29432 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:23.845276 29432 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:23.845326 29432 hybrid_clock.cc:648] HybridClock initialized: now 1786515443845323 us; error 0 us; skew 500 ppm
I20260812 06:17:23.847160 29432 webserver.cc:533] Webserver started at http://127.28.190.62:41799/ using document root <none> and password file <none>
I20260812 06:17:23.847784 29432 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:23.847880 29432 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:23.848173 29432 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:23.850625 29432 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/master-0-root/instance:
uuid: "c583d623c776419595a9d23cad809268"
format_stamp: "Formatted at 2026-08-12 06:17:23 on dist-test-slave-gp6n"
I20260812 06:17:23.855633 29432 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.004s	sys 0.000s
I20260812 06:17:23.858327 29448 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:23.859370 29432 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.001s
I20260812 06:17:23.859494 29432 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/master-0-root
uuid: "c583d623c776419595a9d23cad809268"
format_stamp: "Formatted at 2026-08-12 06:17:23 on dist-test-slave-gp6n"
I20260812 06:17:23.859580 29432 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-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:23.877640 29432 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:23.878257 29432 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:23.878473 29432 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:23.886209 29432 rpc_server.cc:307] RPC server started. Bound to: 127.28.190.62:34367
I20260812 06:17:23.886225 29513 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.28.190.62:34367 every 8 connection(s)
I20260812 06:17:23.888523 29514 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:23.893816 29514 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c583d623c776419595a9d23cad809268: Bootstrap starting.
I20260812 06:17:23.896097 29514 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P c583d623c776419595a9d23cad809268: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:23.896944 29514 log.cc:826] T 00000000000000000000000000000000 P c583d623c776419595a9d23cad809268: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:23.898571 29514 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c583d623c776419595a9d23cad809268: No bootstrap required, opened a new log
I20260812 06:17:23.901142 29514 raft_consensus.cc:359] T 00000000000000000000000000000000 P c583d623c776419595a9d23cad809268 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c583d623c776419595a9d23cad809268" member_type: VOTER }
I20260812 06:17:23.901296 29514 raft_consensus.cc:385] T 00000000000000000000000000000000 P c583d623c776419595a9d23cad809268 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:23.901337 29514 raft_consensus.cc:740] T 00000000000000000000000000000000 P c583d623c776419595a9d23cad809268 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c583d623c776419595a9d23cad809268, State: Initialized, Role: FOLLOWER
I20260812 06:17:23.901921 29514 consensus_queue.cc:260] T 00000000000000000000000000000000 P c583d623c776419595a9d23cad809268 [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: "c583d623c776419595a9d23cad809268" member_type: VOTER }
I20260812 06:17:23.902060 29514 raft_consensus.cc:399] T 00000000000000000000000000000000 P c583d623c776419595a9d23cad809268 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:23.902107 29514 raft_consensus.cc:493] T 00000000000000000000000000000000 P c583d623c776419595a9d23cad809268 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:23.902189 29514 raft_consensus.cc:3060] T 00000000000000000000000000000000 P c583d623c776419595a9d23cad809268 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:23.902949 29514 raft_consensus.cc:515] T 00000000000000000000000000000000 P c583d623c776419595a9d23cad809268 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c583d623c776419595a9d23cad809268" member_type: VOTER }
I20260812 06:17:23.903314 29514 leader_election.cc:304] T 00000000000000000000000000000000 P c583d623c776419595a9d23cad809268 [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: c583d623c776419595a9d23cad809268; no voters: 
I20260812 06:17:23.903571 29514 leader_election.cc:290] T 00000000000000000000000000000000 P c583d623c776419595a9d23cad809268 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:23.903717 29517 raft_consensus.cc:2804] T 00000000000000000000000000000000 P c583d623c776419595a9d23cad809268 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:23.903964 29517 raft_consensus.cc:697] T 00000000000000000000000000000000 P c583d623c776419595a9d23cad809268 [term 1 LEADER]: Becoming Leader. State: Replica: c583d623c776419595a9d23cad809268, State: Running, Role: LEADER
I20260812 06:17:23.904387 29517 consensus_queue.cc:237] T 00000000000000000000000000000000 P c583d623c776419595a9d23cad809268 [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: "c583d623c776419595a9d23cad809268" member_type: VOTER }
I20260812 06:17:23.904620 29514 sys_catalog.cc:565] T 00000000000000000000000000000000 P c583d623c776419595a9d23cad809268 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:23.906430 29520 sys_catalog.cc:455] T 00000000000000000000000000000000 P c583d623c776419595a9d23cad809268 [sys.catalog]: SysCatalogTable state changed. Reason: New leader c583d623c776419595a9d23cad809268. Latest consensus state: current_term: 1 leader_uuid: "c583d623c776419595a9d23cad809268" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c583d623c776419595a9d23cad809268" member_type: VOTER } }
I20260812 06:17:23.906458 29518 sys_catalog.cc:455] T 00000000000000000000000000000000 P c583d623c776419595a9d23cad809268 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "c583d623c776419595a9d23cad809268" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c583d623c776419595a9d23cad809268" member_type: VOTER } }
I20260812 06:17:23.906575 29518 sys_catalog.cc:458] T 00000000000000000000000000000000 P c583d623c776419595a9d23cad809268 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:23.906575 29520 sys_catalog.cc:458] T 00000000000000000000000000000000 P c583d623c776419595a9d23cad809268 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:23.906895 29432 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:17:23.908865 29536 catalog_manager.cc:1594] T 00000000000000000000000000000000 P c583d623c776419595a9d23cad809268: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:17:23.908953 29536 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:17:23.909025 29535 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:23.909758 29535 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:23.914508 29535 catalog_manager.cc:1383] Generated new cluster ID: 3395ba8a945d43b3bb3dfa9965f0a737
I20260812 06:17:23.914562 29535 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:23.927188 29535 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:23.928292 29535 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:23.937073 29535 catalog_manager.cc:6092] T 00000000000000000000000000000000 P c583d623c776419595a9d23cad809268: Generated new TSK 0
I20260812 06:17:23.937860 29535 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:23.939291 29432 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:23.941854 29541 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:23.941923 29543 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:23.941967 29540 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:23.942207 29432 server_base.cc:1061] running on GCE node
I20260812 06:17:23.942484 29432 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:23.942564 29432 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:23.942600 29432 hybrid_clock.cc:648] HybridClock initialized: now 1786515443942599 us; error 0 us; skew 500 ppm
I20260812 06:17:23.943591 29432 webserver.cc:533] Webserver started at http://127.28.190.1:45423/ using document root <none> and password file <none>
I20260812 06:17:23.943763 29432 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:23.943832 29432 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:23.943910 29432 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:23.944273 29432 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root/instance:
uuid: "f3a9ef28d8f940eaa9339b8a7c71c0fd"
format_stamp: "Formatted at 2026-08-12 06:17:23 on dist-test-slave-gp6n"
I20260812 06:17:23.945822 29432 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:23.946822 29549 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:23.947069 29432 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:23.947149 29432 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root
uuid: "f3a9ef28d8f940eaa9339b8a7c71c0fd"
format_stamp: "Formatted at 2026-08-12 06:17:23 on dist-test-slave-gp6n"
I20260812 06:17:23.947258 29432 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-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:23.956326 29432 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:23.956755 29432 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:23.957302 29432 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:23.958120 29432 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:23.958196 29432 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:23.958271 29432 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:23.958321 29432 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:23.965540 29432 rpc_server.cc:307] RPC server started. Bound to: 127.28.190.1:38435
I20260812 06:17:23.965574 29626 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.28.190.1:38435 every 8 connection(s)
I20260812 06:17:23.975203 29628 heartbeater.cc:344] Connected to a master server at 127.28.190.62:34367
I20260812 06:17:23.975481 29628 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:23.975924 29628 heartbeater.cc:507] Master 127.28.190.62:34367 requested a full tablet report, sending...
I20260812 06:17:23.977389 29469 ts_manager.cc:194] Registered new tserver with Master: f3a9ef28d8f940eaa9339b8a7c71c0fd (127.28.190.1:38435)
I20260812 06:17:23.977461 29432 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011235407s
I20260812 06:17:23.978912 29469 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:60272
I20260812 06:17:23.987007 29469 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:60278:
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:24.000885 29581 tablet_service.cc:1511] Processing CreateTablet for tablet bd33dafea3bf433e8ff41112f073adcf (DEFAULT_TABLE table=heavy-update-compaction-test [id=891191e57e2044fab84a2184514dba5f]), partition=
I20260812 06:17:24.001348 29581 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet bd33dafea3bf433e8ff41112f073adcf. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:24.003484 29641 tablet_bootstrap.cc:492] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Bootstrap starting.
I20260812 06:17:24.004578 29641 tablet_bootstrap.cc:654] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:24.005818 29641 tablet_bootstrap.cc:492] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: No bootstrap required, opened a new log
I20260812 06:17:24.005939 29641 ts_tablet_manager.cc:1403] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:24.006386 29641 raft_consensus.cc:359] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f3a9ef28d8f940eaa9339b8a7c71c0fd" member_type: VOTER last_known_addr { host: "127.28.190.1" port: 38435 } }
I20260812 06:17:24.006565 29641 raft_consensus.cc:385] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:24.006613 29641 raft_consensus.cc:740] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f3a9ef28d8f940eaa9339b8a7c71c0fd, State: Initialized, Role: FOLLOWER
I20260812 06:17:24.006752 29641 consensus_queue.cc:260] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd [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: "f3a9ef28d8f940eaa9339b8a7c71c0fd" member_type: VOTER last_known_addr { host: "127.28.190.1" port: 38435 } }
I20260812 06:17:24.006852 29641 raft_consensus.cc:399] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:24.006899 29641 raft_consensus.cc:493] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:24.006954 29641 raft_consensus.cc:3060] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:24.007750 29641 raft_consensus.cc:515] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f3a9ef28d8f940eaa9339b8a7c71c0fd" member_type: VOTER last_known_addr { host: "127.28.190.1" port: 38435 } }
I20260812 06:17:24.007946 29641 leader_election.cc:304] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd [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: f3a9ef28d8f940eaa9339b8a7c71c0fd; no voters: 
I20260812 06:17:24.008154 29641 leader_election.cc:290] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:24.008519 29644 raft_consensus.cc:2804] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:24.008559 29641 ts_tablet_manager.cc:1434] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:17:24.009008 29628 heartbeater.cc:499] Master 127.28.190.62:34367 was elected leader, sending a full tablet report...
I20260812 06:17:24.009030 29644 raft_consensus.cc:697] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd [term 1 LEADER]: Becoming Leader. State: Replica: f3a9ef28d8f940eaa9339b8a7c71c0fd, State: Running, Role: LEADER
I20260812 06:17:24.009208 29644 consensus_queue.cc:237] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd [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: "f3a9ef28d8f940eaa9339b8a7c71c0fd" member_type: VOTER last_known_addr { host: "127.28.190.1" port: 38435 } }
I20260812 06:17:24.012063 29469 catalog_manager.cc:5719] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd reported cstate change: term changed from 0 to 1, leader changed from <none> to f3a9ef28d8f940eaa9339b8a7c71c0fd (127.28.190.1). New cstate: current_term: 1 leader_uuid: "f3a9ef28d8f940eaa9339b8a7c71c0fd" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f3a9ef28d8f940eaa9339b8a7c71c0fd" member_type: VOTER last_known_addr { host: "127.28.190.1" port: 38435 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:24.077229 29432 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.013s	sys 0.012s
I20260812 06:17:24.216706 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushMRSOp(bd33dafea3bf433e8ff41112f073adcf): perf score=19.054940
I20260812 06:17:24.397895 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushMRSOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.181s	user 0.134s	sys 0.039s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":300,"delete_count":0,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":221,"dirs.run_wall_time_us":1104,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43224,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":5888,"thread_start_us":152,"threads_started":1,"update_count":1500}
I20260812 06:17:24.399106 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling LogGCOp(bd33dafea3bf433e8ff41112f073adcf): free 20743880 bytes of WAL
I20260812 06:17:24.399399 29554 log_reader.cc:385] T bd33dafea3bf433e8ff41112f073adcf: removed 2 log segments from log reader
I20260812 06:17:24.399463 29554 log.cc:1079] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/bd33dafea3bf433e8ff41112f073adcf/wal-000000001 (ops 1-6)
I20260812 06:17:24.399525 29554 log.cc:1079] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/bd33dafea3bf433e8ff41112f073adcf/wal-000000002 (ops 7-11)
I20260812 06:17:24.404956 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: LogGCOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:24.405344 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=2.188937
I20260812 06:17:24.422842 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.017s	user 0.017s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6738,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:24.423327 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling UndoDeltaBlockGCOp(bd33dafea3bf433e8ff41112f073adcf): 16411395 bytes on disk
I20260812 06:17:24.423866 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: UndoDeltaBlockGCOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:17:24.424278 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling MajorDeltaCompactionOp(bd33dafea3bf433e8ff41112f073adcf): perf score=1.000000
I20260812 06:17:24.556529 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: MajorDeltaCompactionOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.132s	user 0.091s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":609,"lbm_read_time_us":7511,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23359,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9344,"thread_start_us":365,"threads_started":5,"update_count":2000}
I20260812 06:17:24.557152 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=10.126437
I20260812 06:17:24.597566 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.040s	user 0.021s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17710,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:24.598133 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=2.188937
I20260812 06:17:24.613657 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5635,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:24.614354 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling MajorDeltaCompactionOp(bd33dafea3bf433e8ff41112f073adcf): perf score=1.000000
I20260812 06:17:24.733482 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: MajorDeltaCompactionOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.119s	user 0.094s	sys 0.024s 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":814,"lbm_read_time_us":7761,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25438,"lbm_writes_lt_1ms":443,"mutex_wait_us":45,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9856,"update_count":2000}
I20260812 06:17:24.734037 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=10.126437
I20260812 06:17:24.777915 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.044s	user 0.019s	sys 0.016s Metrics: {"bytes_written":12307540,"delete_count":0,"lbm_write_time_us":17711,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:24.778487 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=2.188937
I20260812 06:17:24.788991 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3895,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:24.789587 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling MajorDeltaCompactionOp(bd33dafea3bf433e8ff41112f073adcf): perf score=1.000000
I20260812 06:17:24.916307 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: MajorDeltaCompactionOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.126s	user 0.096s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672327,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":889,"lbm_read_time_us":9300,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25419,"lbm_writes_lt_1ms":443,"mutex_wait_us":243,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10752,"update_count":2000}
I20260812 06:17:24.916962 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=10.126437
I20260812 06:17:24.973603 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.056s	user 0.030s	sys 0.019s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":18133,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:24.974120 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=2.188937
I20260812 06:17:24.984942 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4248,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:24.985441 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling MajorDeltaCompactionOp(bd33dafea3bf433e8ff41112f073adcf): perf score=1.000000
I20260812 06:17:25.126689 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: MajorDeltaCompactionOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.141s	user 0.093s	sys 0.048s 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":723,"lbm_read_time_us":10634,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24674,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2000}
I20260812 06:17:25.127185 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=10.126437
I20260812 06:17:25.177301 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.050s	user 0.024s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17371,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:25.177805 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=2.188937
I20260812 06:17:25.188443 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4092,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.189138 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling MajorDeltaCompactionOp(bd33dafea3bf433e8ff41112f073adcf): perf score=1.000000
I20260812 06:17:25.311945 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: MajorDeltaCompactionOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.123s	user 0.107s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":207,"lbm_read_time_us":7904,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23259,"lbm_writes_lt_1ms":443,"mutex_wait_us":51,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:25.312788 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=10.126437
I20260812 06:17:25.345079 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.032s	user 0.009s	sys 0.020s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14150,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:25.345577 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=2.188937
I20260812 06:17:25.356436 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4293,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.357007 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling MajorDeltaCompactionOp(bd33dafea3bf433e8ff41112f073adcf): perf score=1.000000
I20260812 06:17:25.481854 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: MajorDeltaCompactionOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.125s	user 0.104s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":221,"lbm_read_time_us":8080,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24223,"lbm_writes_lt_1ms":443,"mutex_wait_us":42,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":2000}
I20260812 06:17:25.482679 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=10.126437
I20260812 06:17:25.522789 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.040s	user 0.025s	sys 0.009s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15050,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:25.523293 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=2.188937
I20260812 06:17:25.533721 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4062,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.534447 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushMRSOp(bd33dafea3bf433e8ff41112f073adcf): perf score=1.000000
I20260812 06:17:25.563889 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushMRSOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.029s	user 0.022s	sys 0.005s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":269,"dirs.run_wall_time_us":1440,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1380,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:25.564656 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling LogGCOp(bd33dafea3bf433e8ff41112f073adcf): free 111786258 bytes of WAL
I20260812 06:17:25.564885 29554 log_reader.cc:385] T bd33dafea3bf433e8ff41112f073adcf: removed 11 log segments from log reader
I20260812 06:17:25.564945 29554 log.cc:1079] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/bd33dafea3bf433e8ff41112f073adcf/wal-000000003 (ops 12-16)
I20260812 06:17:25.564997 29554 log.cc:1079] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/bd33dafea3bf433e8ff41112f073adcf/wal-000000004 (ops 17-21)
I20260812 06:17:25.565056 29554 log.cc:1079] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/bd33dafea3bf433e8ff41112f073adcf/wal-000000005 (ops 22-26)
I20260812 06:17:25.565097 29554 log.cc:1079] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/bd33dafea3bf433e8ff41112f073adcf/wal-000000006 (ops 27-31)
I20260812 06:17:25.565135 29554 log.cc:1079] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/bd33dafea3bf433e8ff41112f073adcf/wal-000000007 (ops 32-36)
I20260812 06:17:25.565171 29554 log.cc:1079] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/bd33dafea3bf433e8ff41112f073adcf/wal-000000008 (ops 37-40)
I20260812 06:17:25.565209 29554 log.cc:1079] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/bd33dafea3bf433e8ff41112f073adcf/wal-000000009 (ops 41-45)
I20260812 06:17:25.565246 29554 log.cc:1079] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/bd33dafea3bf433e8ff41112f073adcf/wal-000000010 (ops 46-50)
I20260812 06:17:25.565282 29554 log.cc:1079] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/bd33dafea3bf433e8ff41112f073adcf/wal-000000011 (ops 51-55)
I20260812 06:17:25.565318 29554 log.cc:1079] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/bd33dafea3bf433e8ff41112f073adcf/wal-000000012 (ops 56-60)
I20260812 06:17:25.565353 29554 log.cc:1079] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/bd33dafea3bf433e8ff41112f073adcf/wal-000000013 (ops 61-64)
I20260812 06:17:25.589412 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: LogGCOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.025s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:17:25.589789 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling UndoDeltaBlockGCOp(bd33dafea3bf433e8ff41112f073adcf): 447 bytes on disk
I20260812 06:17:25.590189 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: UndoDeltaBlockGCOp(bd33dafea3bf433e8ff41112f073adcf) 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:25.590677 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=3.181125
I20260812 06:17:25.603668 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.013s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4125,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:25.604015 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=2.188937
I20260812 06:17:25.613443 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3482,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:25.613853 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling MajorDeltaCompactionOp(bd33dafea3bf433e8ff41112f073adcf): perf score=1.000000
I20260812 06:17:25.777055 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: MajorDeltaCompactionOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.163s	user 0.142s	sys 0.020s 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":118,"lbm_read_time_us":11242,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33477,"lbm_writes_lt_1ms":643,"mutex_wait_us":21,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6528,"thread_start_us":99,"threads_started":1,"update_count":3000}
I20260812 06:17:25.777670 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=14.095187
I20260812 06:17:25.823688 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.046s	user 0.025s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20460,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:25.824213 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=2.188937
I20260812 06:17:25.838788 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.014s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5813,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.839231 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling MajorDeltaCompactionOp(bd33dafea3bf433e8ff41112f073adcf): perf score=1.000000
I20260812 06:17:25.987567 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: MajorDeltaCompactionOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.148s	user 0.126s	sys 0.017s 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":162,"lbm_read_time_us":9515,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30694,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15616,"update_count":2500}
I20260812 06:17:25.988183 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=14.095187
I20260812 06:17:26.040088 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.052s	user 0.032s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22242,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:26.040663 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=2.188937
I20260812 06:17:26.054981 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5824,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.055459 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling MajorDeltaCompactionOp(bd33dafea3bf433e8ff41112f073adcf): perf score=1.000000
I20260812 06:17:26.213544 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: MajorDeltaCompactionOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.158s	user 0.108s	sys 0.043s 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":904,"lbm_read_time_us":9524,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28306,"lbm_writes_lt_1ms":543,"mutex_wait_us":351,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:26.214128 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=14.095187
I20260812 06:17:26.281339 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.067s	user 0.032s	sys 0.020s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":26531,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:26.281842 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=2.188937
I20260812 06:17:26.292538 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3863,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.293046 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling MajorDeltaCompactionOp(bd33dafea3bf433e8ff41112f073adcf): perf score=1.000000
I20260812 06:17:26.472672 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: MajorDeltaCompactionOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.179s	user 0.131s	sys 0.040s 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":408,"lbm_read_time_us":12356,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29470,"lbm_writes_lt_1ms":543,"mutex_wait_us":110,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13696,"update_count":2500}
I20260812 06:17:26.473418 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=14.095187
I20260812 06:17:26.532625 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.059s	user 0.031s	sys 0.019s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":22740,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:26.533241 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=2.188937
I20260812 06:17:26.550316 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.017s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6592,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.550928 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling MajorDeltaCompactionOp(bd33dafea3bf433e8ff41112f073adcf): perf score=1.000000
I20260812 06:17:26.714316 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: MajorDeltaCompactionOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.163s	user 0.125s	sys 0.034s 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":751,"lbm_read_time_us":11807,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28393,"lbm_writes_lt_1ms":543,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:26.715095 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=14.095187
I20260812 06:17:26.773339 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.058s	user 0.022s	sys 0.032s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23490,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:26.773921 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=2.188937
I20260812 06:17:26.785264 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4195,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.787477 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling MajorDeltaCompactionOp(bd33dafea3bf433e8ff41112f073adcf): perf score=1.000000
I20260812 06:17:26.978444 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: MajorDeltaCompactionOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.191s	user 0.119s	sys 0.061s 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":385,"lbm_read_time_us":11386,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32026,"lbm_writes_lt_1ms":543,"mutex_wait_us":69,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:26.979135 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=14.095187
I20260812 06:17:27.033108 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.054s	user 0.042s	sys 0.003s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21430,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:27.033670 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=2.188937
I20260812 06:17:27.052520 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.019s	user 0.002s	sys 0.015s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4266,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.052978 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushMRSOp(bd33dafea3bf433e8ff41112f073adcf): perf score=1.000000
I20260812 06:17:27.087724 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushMRSOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.035s	user 0.029s	sys 0.004s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":236,"dirs.run_wall_time_us":1470,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1672,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:27.088428 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling LogGCOp(bd33dafea3bf433e8ff41112f073adcf): free 137634524 bytes of WAL
I20260812 06:17:27.088652 29554 log_reader.cc:385] T bd33dafea3bf433e8ff41112f073adcf: removed 14 log segments from log reader
I20260812 06:17:27.088711 29554 log.cc:1079] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/bd33dafea3bf433e8ff41112f073adcf/wal-000000014 (ops 65-69)
I20260812 06:17:27.088765 29554 log.cc:1079] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/bd33dafea3bf433e8ff41112f073adcf/wal-000000015 (ops 70-74)
I20260812 06:17:27.088821 29554 log.cc:1079] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/bd33dafea3bf433e8ff41112f073adcf/wal-000000016 (ops 75-78)
I20260812 06:17:27.088862 29554 log.cc:1079] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/bd33dafea3bf433e8ff41112f073adcf/wal-000000017 (ops 79-83)
I20260812 06:17:27.088899 29554 log.cc:1079] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/bd33dafea3bf433e8ff41112f073adcf/wal-000000018 (ops 84-88)
I20260812 06:17:27.088936 29554 log.cc:1079] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/bd33dafea3bf433e8ff41112f073adcf/wal-000000019 (ops 89-92)
I20260812 06:17:27.088973 29554 log.cc:1079] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/bd33dafea3bf433e8ff41112f073adcf/wal-000000020 (ops 93-97)
I20260812 06:17:27.089010 29554 log.cc:1079] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/bd33dafea3bf433e8ff41112f073adcf/wal-000000021 (ops 98-102)
I20260812 06:17:27.089046 29554 log.cc:1079] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/bd33dafea3bf433e8ff41112f073adcf/wal-000000022 (ops 103-106)
I20260812 06:17:27.089082 29554 log.cc:1079] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/bd33dafea3bf433e8ff41112f073adcf/wal-000000023 (ops 107-111)
I20260812 06:17:27.089116 29554 log.cc:1079] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/bd33dafea3bf433e8ff41112f073adcf/wal-000000024 (ops 112-116)
I20260812 06:17:27.089152 29554 log.cc:1079] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/bd33dafea3bf433e8ff41112f073adcf/wal-000000025 (ops 117-121)
I20260812 06:17:27.089188 29554 log.cc:1079] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/bd33dafea3bf433e8ff41112f073adcf/wal-000000026 (ops 122-126)
I20260812 06:17:27.089223 29554 log.cc:1079] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/bd33dafea3bf433e8ff41112f073adcf/wal-000000027 (ops 127-131)
I20260812 06:17:27.118796 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: LogGCOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.030s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:17:27.119234 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling UndoDeltaBlockGCOp(bd33dafea3bf433e8ff41112f073adcf): 492 bytes on disk
I20260812 06:17:27.119750 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: UndoDeltaBlockGCOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:17:27.120343 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=3.181125
I20260812 06:17:27.134282 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.014s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4563,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:27.134681 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=2.188937
I20260812 06:17:27.143829 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.009s	user 0.002s	sys 0.006s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3448,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:27.144279 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling MajorDeltaCompactionOp(bd33dafea3bf433e8ff41112f073adcf): perf score=1.000000
I20260812 06:17:27.378147 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: MajorDeltaCompactionOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.234s	user 0.146s	sys 0.076s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979739,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":442,"lbm_read_time_us":14666,"lbm_reads_lt_1ms":774,"lbm_write_time_us":37351,"lbm_writes_lt_1ms":743,"mutex_wait_us":20,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":19840,"thread_start_us":82,"threads_started":1,"update_count":3500}
I20260812 06:17:27.378921 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=18.063937
I20260812 06:17:27.444859 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.065s	user 0.038s	sys 0.015s Metrics: {"bytes_written":20512314,"delete_count":0,"lbm_write_time_us":25053,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:27.445361 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=2.188937
I20260812 06:17:27.457019 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4534,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.457584 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling MajorDeltaCompactionOp(bd33dafea3bf433e8ff41112f073adcf): perf score=1.000000
I20260812 06:17:27.664858 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: MajorDeltaCompactionOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.207s	user 0.130s	sys 0.071s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877101,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":408,"lbm_read_time_us":14332,"lbm_reads_lt_1ms":672,"lbm_write_time_us":31298,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:17:27.665503 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=14.095187
I20260812 06:17:27.741453 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.076s	user 0.035s	sys 0.029s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":29518,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:17:27.741936 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=2.188937
I20260812 06:17:27.753131 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4126,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.753882 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling MajorDeltaCompactionOp(bd33dafea3bf433e8ff41112f073adcf): perf score=1.000000
I20260812 06:17:27.933569 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: MajorDeltaCompactionOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.179s	user 0.134s	sys 0.041s 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":320,"lbm_read_time_us":13613,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29853,"lbm_writes_lt_1ms":543,"mutex_wait_us":55,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2500}
I20260812 06:17:27.934324 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=14.095187
I20260812 06:17:27.989264 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.055s	user 0.047s	sys 0.005s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24182,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:27.989847 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=2.188937
I20260812 06:17:28.004632 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5361,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.005473 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling MajorDeltaCompactionOp(bd33dafea3bf433e8ff41112f073adcf): perf score=1.000000
I20260812 06:17:28.189987 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: MajorDeltaCompactionOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.184s	user 0.122s	sys 0.061s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1792,"lbm_read_time_us":12375,"lbm_reads_lt_1ms":564,"lbm_write_time_us":32542,"lbm_writes_lt_1ms":543,"mutex_wait_us":1144,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:17:28.190657 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=14.095187
I20260812 06:17:28.246866 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.056s	user 0.040s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20433,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:28.247761 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=2.188937
I20260812 06:17:28.265018 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.017s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6700,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.265606 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling MajorDeltaCompactionOp(bd33dafea3bf433e8ff41112f073adcf): perf score=1.000000
I20260812 06:17:28.428493 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: MajorDeltaCompactionOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.163s	user 0.086s	sys 0.076s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1048,"lbm_read_time_us":10521,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28345,"lbm_writes_lt_1ms":543,"mutex_wait_us":312,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2500}
I20260812 06:17:28.429159 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=14.095187
I20260812 06:17:28.477695 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.048s	user 0.032s	sys 0.011s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20283,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:28.478276 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=2.188937
I20260812 06:17:28.499276 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.021s	user 0.004s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3981,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.500016 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushMRSOp(bd33dafea3bf433e8ff41112f073adcf): perf score=1.000000
I20260812 06:17:28.530041 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushMRSOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.030s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":243,"dirs.run_wall_time_us":1521,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1552,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:28.530833 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling LogGCOp(bd33dafea3bf433e8ff41112f073adcf): free 112239554 bytes of WAL
I20260812 06:17:28.531050 29554 log_reader.cc:385] T bd33dafea3bf433e8ff41112f073adcf: removed 11 log segments from log reader
I20260812 06:17:28.531092 29554 log.cc:1079] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/bd33dafea3bf433e8ff41112f073adcf/wal-000000028 (ops 132-136)
I20260812 06:17:28.531119 29554 log.cc:1079] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/bd33dafea3bf433e8ff41112f073adcf/wal-000000029 (ops 137-141)
I20260812 06:17:28.531179 29554 log.cc:1079] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/bd33dafea3bf433e8ff41112f073adcf/wal-000000030 (ops 142-146)
I20260812 06:17:28.531224 29554 log.cc:1079] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/bd33dafea3bf433e8ff41112f073adcf/wal-000000031 (ops 147-150)
I20260812 06:17:28.531263 29554 log.cc:1079] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/bd33dafea3bf433e8ff41112f073adcf/wal-000000032 (ops 151-155)
I20260812 06:17:28.531306 29554 log.cc:1079] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/bd33dafea3bf433e8ff41112f073adcf/wal-000000033 (ops 156-160)
I20260812 06:17:28.531347 29554 log.cc:1079] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/bd33dafea3bf433e8ff41112f073adcf/wal-000000034 (ops 161-165)
I20260812 06:17:28.531387 29554 log.cc:1079] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/bd33dafea3bf433e8ff41112f073adcf/wal-000000035 (ops 166-170)
I20260812 06:17:28.531423 29554 log.cc:1079] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/bd33dafea3bf433e8ff41112f073adcf/wal-000000036 (ops 171-175)
I20260812 06:17:28.531462 29554 log.cc:1079] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/bd33dafea3bf433e8ff41112f073adcf/wal-000000037 (ops 176-180)
I20260812 06:17:28.531508 29554 log.cc:1079] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/bd33dafea3bf433e8ff41112f073adcf/wal-000000038 (ops 181-185)
I20260812 06:17:28.554740 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: LogGCOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.024s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:17:28.555186 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=2.188937
I20260812 06:17:28.576584 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.021s	user 0.013s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6171,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.577052 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=2.188937
I20260812 06:17:28.587123 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3803,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.587863 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling UndoDeltaBlockGCOp(bd33dafea3bf433e8ff41112f073adcf): 448 bytes on disk
I20260812 06:17:28.588397 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: UndoDeltaBlockGCOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4}
I20260812 06:17:28.589016 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling MajorDeltaCompactionOp(bd33dafea3bf433e8ff41112f073adcf): perf score=1.000000
I20260812 06:17:28.825235 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: MajorDeltaCompactionOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.236s	user 0.154s	sys 0.074s 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":1074,"lbm_read_time_us":14103,"lbm_reads_lt_1ms":774,"lbm_write_time_us":38009,"lbm_writes_lt_1ms":743,"mutex_wait_us":25,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":83,"threads_started":1,"update_count":3500}
I20260812 06:17:28.826078 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf): perf score=18.063937
I20260812 06:17:28.883750 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: FlushDeltaMemStoresOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.057s	user 0.031s	sys 0.024s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":26321,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:28.884215 29629 maintenance_manager.cc:419] P f3a9ef28d8f940eaa9339b8a7c71c0fd: Scheduling MajorDeltaCompactionOp(bd33dafea3bf433e8ff41112f073adcf): perf score=1.000000
I20260812 06:17:28.903352 29432 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.826s	user 1.786s	sys 0.198s
I20260812 06:17:28.975129 29432 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.071s	user 0.005s	sys 0.000s
I20260812 06:17:28.975905 29432 tablet_server.cc:179] TabletServer@127.28.190.1:0 shutting down...
I20260812 06:17:29.033181 29554 maintenance_manager.cc:643] P f3a9ef28d8f940eaa9339b8a7c71c0fd: MajorDeltaCompactionOp(bd33dafea3bf433e8ff41112f073adcf) complete. Timing: real 0.149s	user 0.108s	sys 0.040s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24774572,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":571,"lbm_read_time_us":11518,"lbm_reads_lt_1ms":563,"lbm_write_time_us":25883,"lbm_writes_lt_1ms":543,"mutex_wait_us":130,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:29.033946 29432 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:29.034318 29432 tablet_replica.cc:333] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd: stopping tablet replica
I20260812 06:17:29.034590 29432 raft_consensus.cc:2243] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:29.034825 29432 raft_consensus.cc:2272] T bd33dafea3bf433e8ff41112f073adcf P f3a9ef28d8f940eaa9339b8a7c71c0fd [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:29.051903 29432 tablet_server.cc:196] TabletServer@127.28.190.1:0 shutdown complete.
I20260812 06:17:29.080039 29432 master.cc:562] Master@127.28.190.62:34367 shutting down...
I20260812 06:17:29.084264 29432 raft_consensus.cc:2243] T 00000000000000000000000000000000 P c583d623c776419595a9d23cad809268 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:29.084474 29432 raft_consensus.cc:2272] T 00000000000000000000000000000000 P c583d623c776419595a9d23cad809268 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:29.084578 29432 tablet_replica.cc:333] T 00000000000000000000000000000000 P c583d623c776419595a9d23cad809268: stopping tablet replica
I20260812 06:17:29.097028 29432 master.cc:584] Master@127.28.190.62:34367 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5350 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:29.199785 29432 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.28.190.62:42445
I20260812 06:17:29.200184 29432 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:17:29.202724 29432 server_base.cc:1061] running on GCE node
W20260812 06:17:29.202814 29661 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:29.202894 29663 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:29.202816 29660 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:29.203173 29432 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:29.203220 29432 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:29.203239 29432 hybrid_clock.cc:648] HybridClock initialized: now 1786515449203239 us; error 0 us; skew 500 ppm
I20260812 06:17:29.204097 29432 webserver.cc:533] Webserver started at http://127.28.190.62:32967/ using document root <none> and password file <none>
I20260812 06:17:29.204229 29432 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:29.204273 29432 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:29.204325 29432 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:29.204715 29432 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/master-0-root/instance:
uuid: "9173b1cf56884bc6b15d421ddab032d9"
format_stamp: "Formatted at 2026-08-12 06:17:29 on dist-test-slave-gp6n"
I20260812 06:17:29.206202 29432 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:29.207242 29672 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:29.207573 29432 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:29.207645 29432 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/master-0-root
uuid: "9173b1cf56884bc6b15d421ddab032d9"
format_stamp: "Formatted at 2026-08-12 06:17:29 on dist-test-slave-gp6n"
I20260812 06:17:29.207700 29432 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-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:29.212397 29432 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:29.212693 29432 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:29.216614 29432 rpc_server.cc:307] RPC server started. Bound to: 127.28.190.62:42445
I20260812 06:17:29.219748 29731 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.28.190.62:42445 every 8 connection(s)
I20260812 06:17:29.220170 29732 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:29.221863 29732 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 9173b1cf56884bc6b15d421ddab032d9: Bootstrap starting.
I20260812 06:17:29.222726 29732 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 9173b1cf56884bc6b15d421ddab032d9: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:29.223742 29732 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 9173b1cf56884bc6b15d421ddab032d9: No bootstrap required, opened a new log
I20260812 06:17:29.224143 29732 raft_consensus.cc:359] T 00000000000000000000000000000000 P 9173b1cf56884bc6b15d421ddab032d9 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9173b1cf56884bc6b15d421ddab032d9" member_type: VOTER }
I20260812 06:17:29.224223 29732 raft_consensus.cc:385] T 00000000000000000000000000000000 P 9173b1cf56884bc6b15d421ddab032d9 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:29.224244 29732 raft_consensus.cc:740] T 00000000000000000000000000000000 P 9173b1cf56884bc6b15d421ddab032d9 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 9173b1cf56884bc6b15d421ddab032d9, State: Initialized, Role: FOLLOWER
I20260812 06:17:29.224432 29732 consensus_queue.cc:260] T 00000000000000000000000000000000 P 9173b1cf56884bc6b15d421ddab032d9 [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: "9173b1cf56884bc6b15d421ddab032d9" member_type: VOTER }
I20260812 06:17:29.224503 29732 raft_consensus.cc:399] T 00000000000000000000000000000000 P 9173b1cf56884bc6b15d421ddab032d9 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:29.224545 29732 raft_consensus.cc:493] T 00000000000000000000000000000000 P 9173b1cf56884bc6b15d421ddab032d9 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:29.224608 29732 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 9173b1cf56884bc6b15d421ddab032d9 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:29.225288 29732 raft_consensus.cc:515] T 00000000000000000000000000000000 P 9173b1cf56884bc6b15d421ddab032d9 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9173b1cf56884bc6b15d421ddab032d9" member_type: VOTER }
I20260812 06:17:29.225418 29732 leader_election.cc:304] T 00000000000000000000000000000000 P 9173b1cf56884bc6b15d421ddab032d9 [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: 9173b1cf56884bc6b15d421ddab032d9; no voters: 
I20260812 06:17:29.225636 29732 leader_election.cc:290] T 00000000000000000000000000000000 P 9173b1cf56884bc6b15d421ddab032d9 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:29.225835 29735 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 9173b1cf56884bc6b15d421ddab032d9 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:29.226066 29732 sys_catalog.cc:565] T 00000000000000000000000000000000 P 9173b1cf56884bc6b15d421ddab032d9 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:29.226097 29735 raft_consensus.cc:697] T 00000000000000000000000000000000 P 9173b1cf56884bc6b15d421ddab032d9 [term 1 LEADER]: Becoming Leader. State: Replica: 9173b1cf56884bc6b15d421ddab032d9, State: Running, Role: LEADER
I20260812 06:17:29.226227 29735 consensus_queue.cc:237] T 00000000000000000000000000000000 P 9173b1cf56884bc6b15d421ddab032d9 [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: "9173b1cf56884bc6b15d421ddab032d9" member_type: VOTER }
I20260812 06:17:29.226856 29738 sys_catalog.cc:455] T 00000000000000000000000000000000 P 9173b1cf56884bc6b15d421ddab032d9 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 9173b1cf56884bc6b15d421ddab032d9. Latest consensus state: current_term: 1 leader_uuid: "9173b1cf56884bc6b15d421ddab032d9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9173b1cf56884bc6b15d421ddab032d9" member_type: VOTER } }
I20260812 06:17:29.226943 29738 sys_catalog.cc:458] T 00000000000000000000000000000000 P 9173b1cf56884bc6b15d421ddab032d9 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:29.227156 29736 sys_catalog.cc:455] T 00000000000000000000000000000000 P 9173b1cf56884bc6b15d421ddab032d9 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "9173b1cf56884bc6b15d421ddab032d9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9173b1cf56884bc6b15d421ddab032d9" member_type: VOTER } }
I20260812 06:17:29.227262 29736 sys_catalog.cc:458] T 00000000000000000000000000000000 P 9173b1cf56884bc6b15d421ddab032d9 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:29.227531 29746 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:29.228365 29746 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:29.228613 29432 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:29.230274 29746 catalog_manager.cc:1383] Generated new cluster ID: ced11472101c4442bdc9fc730724d2cd
I20260812 06:17:29.230343 29746 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:29.251356 29746 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:29.251930 29746 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:29.262089 29746 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 9173b1cf56884bc6b15d421ddab032d9: Generated new TSK 0
I20260812 06:17:29.262262 29746 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:29.293857 29432 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:29.297139 29760 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:29.297174 29757 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:29.297175 29758 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:29.297451 29432 server_base.cc:1061] running on GCE node
I20260812 06:17:29.297885 29432 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:29.297950 29432 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:29.297971 29432 hybrid_clock.cc:648] HybridClock initialized: now 1786515449297970 us; error 0 us; skew 500 ppm
I20260812 06:17:29.299458 29432 webserver.cc:533] Webserver started at http://127.28.190.1:35381/ using document root <none> and password file <none>
I20260812 06:17:29.299726 29432 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:29.299832 29432 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:29.299971 29432 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:29.300684 29432 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root/instance:
uuid: "92acd8c3a785416cb5a55474846a9634"
format_stamp: "Formatted at 2026-08-12 06:17:29 on dist-test-slave-gp6n"
I20260812 06:17:29.304189 29432 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.002s	sys 0.002s
I20260812 06:17:29.305884 29765 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:29.306367 29432 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:29.306557 29432 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root
uuid: "92acd8c3a785416cb5a55474846a9634"
format_stamp: "Formatted at 2026-08-12 06:17:29 on dist-test-slave-gp6n"
I20260812 06:17:29.306646 29432 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-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:29.315745 29432 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:29.316346 29432 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:29.316744 29432 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:29.317531 29432 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:29.317582 29432 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:29.317667 29432 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:29.317736 29432 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:29.325558 29432 rpc_server.cc:307] RPC server started. Bound to: 127.28.190.1:40143
I20260812 06:17:29.327625 29838 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.28.190.1:40143 every 8 connection(s)
I20260812 06:17:29.338682 29839 heartbeater.cc:344] Connected to a master server at 127.28.190.62:42445
I20260812 06:17:29.338898 29839 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:29.339293 29839 heartbeater.cc:507] Master 127.28.190.62:42445 requested a full tablet report, sending...
I20260812 06:17:29.340243 29691 ts_manager.cc:194] Registered new tserver with Master: 92acd8c3a785416cb5a55474846a9634 (127.28.190.1:40143)
I20260812 06:17:29.341221 29432 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013606596s
I20260812 06:17:29.341459 29691 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:56882
I20260812 06:17:29.353088 29691 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:56894:
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:29.367280 29796 tablet_service.cc:1511] Processing CreateTablet for tablet 4643b06ec4c047f2be7c7709d8b794ca (DEFAULT_TABLE table=heavy-update-compaction-test [id=c314ffd3858a4f87bded55b36cc0f032]), partition=
I20260812 06:17:29.367800 29796 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 4643b06ec4c047f2be7c7709d8b794ca. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:29.371279 29855 tablet_bootstrap.cc:492] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Bootstrap starting.
I20260812 06:17:29.372838 29855 tablet_bootstrap.cc:654] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:29.374437 29855 tablet_bootstrap.cc:492] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: No bootstrap required, opened a new log
I20260812 06:17:29.374562 29855 ts_tablet_manager.cc:1403] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Time spent bootstrapping tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:29.375317 29855 raft_consensus.cc:359] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "92acd8c3a785416cb5a55474846a9634" member_type: VOTER last_known_addr { host: "127.28.190.1" port: 40143 } }
I20260812 06:17:29.375558 29855 raft_consensus.cc:385] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:29.375670 29855 raft_consensus.cc:740] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 92acd8c3a785416cb5a55474846a9634, State: Initialized, Role: FOLLOWER
I20260812 06:17:29.375965 29855 consensus_queue.cc:260] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634 [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: "92acd8c3a785416cb5a55474846a9634" member_type: VOTER last_known_addr { host: "127.28.190.1" port: 40143 } }
I20260812 06:17:29.376104 29855 raft_consensus.cc:399] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:29.376197 29855 raft_consensus.cc:493] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:29.376295 29855 raft_consensus.cc:3060] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:29.377400 29855 raft_consensus.cc:515] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "92acd8c3a785416cb5a55474846a9634" member_type: VOTER last_known_addr { host: "127.28.190.1" port: 40143 } }
I20260812 06:17:29.377591 29855 leader_election.cc:304] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634 [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: 92acd8c3a785416cb5a55474846a9634; no voters: 
I20260812 06:17:29.377858 29855 leader_election.cc:290] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:29.378082 29857 raft_consensus.cc:2804] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:29.378593 29839 heartbeater.cc:499] Master 127.28.190.62:42445 was elected leader, sending a full tablet report...
I20260812 06:17:29.378569 29857 raft_consensus.cc:697] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634 [term 1 LEADER]: Becoming Leader. State: Replica: 92acd8c3a785416cb5a55474846a9634, State: Running, Role: LEADER
I20260812 06:17:29.378681 29855 ts_tablet_manager.cc:1434] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Time spent starting tablet: real 0.004s	user 0.004s	sys 0.000s
I20260812 06:17:29.378921 29857 consensus_queue.cc:237] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634 [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: "92acd8c3a785416cb5a55474846a9634" member_type: VOTER last_known_addr { host: "127.28.190.1" port: 40143 } }
I20260812 06:17:29.381243 29691 catalog_manager.cc:5719] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634 reported cstate change: term changed from 0 to 1, leader changed from <none> to 92acd8c3a785416cb5a55474846a9634 (127.28.190.1). New cstate: current_term: 1 leader_uuid: "92acd8c3a785416cb5a55474846a9634" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "92acd8c3a785416cb5a55474846a9634" member_type: VOTER last_known_addr { host: "127.28.190.1" port: 40143 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:29.486728 29432 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.097s	user 0.037s	sys 0.008s
I20260812 06:17:29.579046 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushMRSOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=6.156503
I20260812 06:17:29.775345 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushMRSOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.196s	user 0.139s	sys 0.045s Metrics: {"bytes_written":8205078,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":108,"dirs.run_cpu_time_us":378,"dirs.run_wall_time_us":1125,"drs_written":1,"lbm_read_time_us":92,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44098,"lbm_writes_lt_1ms":357,"peak_mem_usage":0,"reinsert_count":0,"rows_written":101,"update_count":1000}
I20260812 06:17:29.776530 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling UndoDeltaBlockGCOp(4643b06ec4c047f2be7c7709d8b794ca): 4103816 bytes on disk
I20260812 06:17:29.777201 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: UndoDeltaBlockGCOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":141,"lbm_reads_lt_1ms":4}
I20260812 06:17:29.777854 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=2.188937
I20260812 06:17:29.797199 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.019s	user 0.014s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7568,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.797941 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling MajorDeltaCompactionOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=1.000000
I20260812 06:17:30.013411 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: MajorDeltaCompactionOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.215s	user 0.148s	sys 0.060s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16446970,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1262,"lbm_read_time_us":15929,"lbm_reads_lt_1ms":364,"lbm_write_time_us":34529,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":14976,"thread_start_us":590,"threads_started":5,"update_count":1500}
I20260812 06:17:30.014465 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=10.126437
I20260812 06:17:30.116843 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.102s	user 0.052s	sys 0.026s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":36992,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:30.117625 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=2.188937
I20260812 06:17:30.138947 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.021s	user 0.013s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7771,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.139952 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling MajorDeltaCompactionOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=1.000000
I20260812 06:17:30.363158 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: MajorDeltaCompactionOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.223s	user 0.175s	sys 0.047s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20549382,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":684,"lbm_read_time_us":18303,"lbm_reads_lt_1ms":472,"lbm_write_time_us":44921,"lbm_writes_lt_1ms":443,"mutex_wait_us":120,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2000}
I20260812 06:17:30.364024 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=10.126437
I20260812 06:17:30.443889 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.080s	user 0.051s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":28408,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:30.444677 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=2.188937
I20260812 06:17:30.463694 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.019s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7866,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.464311 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling MajorDeltaCompactionOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=1.000000
I20260812 06:17:30.709576 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: MajorDeltaCompactionOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.245s	user 0.163s	sys 0.079s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20549382,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":201,"lbm_read_time_us":19587,"lbm_reads_lt_1ms":472,"lbm_write_time_us":43275,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2000}
I20260812 06:17:30.710986 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=10.126437
I20260812 06:17:30.794715 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.083s	user 0.037s	sys 0.044s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":34912,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:17:30.795532 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=2.188937
I20260812 06:17:30.816303 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.021s	user 0.015s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":8195,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.816771 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling MajorDeltaCompactionOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=1.000000
I20260812 06:17:31.040369 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: MajorDeltaCompactionOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.223s	user 0.160s	sys 0.059s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20549384,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":116,"lbm_read_time_us":15971,"lbm_reads_lt_1ms":472,"lbm_write_time_us":48018,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2000}
I20260812 06:17:31.041461 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=10.126437
I20260812 06:17:31.106045 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.063s	user 0.027s	sys 0.033s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":30575,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:17:31.107009 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=2.188937
I20260812 06:17:31.161088 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.054s	user 0.022s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":11339,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.162065 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=2.188937
I20260812 06:17:31.181962 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.020s	user 0.010s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7674,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.183058 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling MajorDeltaCompactionOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=1.000000
I20260812 06:17:31.466763 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: MajorDeltaCompactionOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.283s	user 0.199s	sys 0.084s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24651913,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":418,"lbm_read_time_us":18813,"lbm_reads_lt_1ms":573,"lbm_write_time_us":68401,"lbm_writes_lt_1ms":543,"mutex_wait_us":44,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12288,"update_count":2500}
I20260812 06:17:31.467908 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=10.126437
I20260812 06:17:31.540385 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.072s	user 0.045s	sys 0.025s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":33713,"lbm_writes_1-10_ms":4,"lbm_writes_lt_1ms":299,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1500}
I20260812 06:17:31.541247 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=2.188937
I20260812 06:17:31.592262 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.051s	user 0.007s	sys 0.021s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":12768,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.593205 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=2.188937
I20260812 06:17:31.617841 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.024s	user 0.009s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":9457,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.618831 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling MajorDeltaCompactionOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=1.000000
I20260812 06:17:31.923385 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: MajorDeltaCompactionOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.304s	user 0.216s	sys 0.084s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24651913,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":892,"lbm_read_time_us":22540,"lbm_reads_lt_1ms":573,"lbm_write_time_us":59670,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2500}
I20260812 06:17:31.924296 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=11.118625
I20260812 06:17:31.995201 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.071s	user 0.034s	sys 0.036s Metrics: {"bytes_written":13456167,"delete_count":0,"lbm_write_time_us":32271,"lbm_writes_lt_1ms":331,"mutex_wait_us":252,"reinsert_count":0,"update_count":1640}
I20260812 06:17:31.996114 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=1.196750
I20260812 06:17:32.018024 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.022s	user 0.014s	sys 0.004s Metrics: {"bytes_written":2994984,"delete_count":0,"lbm_write_time_us":7625,"lbm_writes_lt_1ms":76,"reinsert_count":0,"update_count":365}
I20260812 06:17:32.019061 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushMRSOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=1.000000
I20260812 06:17:32.104538 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushMRSOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.085s	user 0.057s	sys 0.000s Metrics: {"bytes_written":1234474,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":225,"dirs.run_wall_time_us":1406,"drs_written":1,"lbm_read_time_us":200,"lbm_reads_lt_1ms":4,"lbm_write_time_us":3040,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:32.105927 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=3.181125
I20260812 06:17:32.135456 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.029s	user 0.015s	sys 0.008s Metrics: {"bytes_written":4348810,"delete_count":0,"lbm_write_time_us":9214,"lbm_writes_lt_1ms":109,"reinsert_count":0,"update_count":530}
I20260812 06:17:32.136263 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling LogGCOp(4643b06ec4c047f2be7c7709d8b794ca): free 124669087 bytes of WAL
I20260812 06:17:32.136616 29770 log_reader.cc:385] T 4643b06ec4c047f2be7c7709d8b794ca: removed 12 log segments from log reader
I20260812 06:17:32.136674 29770 log.cc:1079] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/4643b06ec4c047f2be7c7709d8b794ca/wal-000000001 (ops 1-6)
I20260812 06:17:32.136734 29770 log.cc:1079] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/4643b06ec4c047f2be7c7709d8b794ca/wal-000000002 (ops 7-11)
I20260812 06:17:32.136837 29770 log.cc:1079] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/4643b06ec4c047f2be7c7709d8b794ca/wal-000000003 (ops 12-16)
I20260812 06:17:32.136976 29770 log.cc:1079] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/4643b06ec4c047f2be7c7709d8b794ca/wal-000000004 (ops 17-21)
I20260812 06:17:32.137082 29770 log.cc:1079] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/4643b06ec4c047f2be7c7709d8b794ca/wal-000000005 (ops 22-26)
I20260812 06:17:32.137176 29770 log.cc:1079] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/4643b06ec4c047f2be7c7709d8b794ca/wal-000000006 (ops 27-31)
I20260812 06:17:32.137274 29770 log.cc:1079] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/4643b06ec4c047f2be7c7709d8b794ca/wal-000000007 (ops 32-36)
I20260812 06:17:32.137389 29770 log.cc:1079] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/4643b06ec4c047f2be7c7709d8b794ca/wal-000000008 (ops 37-41)
I20260812 06:17:32.137488 29770 log.cc:1079] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/4643b06ec4c047f2be7c7709d8b794ca/wal-000000009 (ops 42-46)
I20260812 06:17:32.137566 29770 log.cc:1079] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/4643b06ec4c047f2be7c7709d8b794ca/wal-000000010 (ops 47-51)
I20260812 06:17:32.137636 29770 log.cc:1079] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/4643b06ec4c047f2be7c7709d8b794ca/wal-000000011 (ops 52-56)
I20260812 06:17:32.137692 29770 log.cc:1079] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/4643b06ec4c047f2be7c7709d8b794ca/wal-000000012 (ops 57-61)
I20260812 06:17:32.181555 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: LogGCOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.045s	user 0.000s	sys 0.042s Metrics: {}
I20260812 06:17:32.182257 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=2.188937
I20260812 06:17:32.236508 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.054s	user 0.016s	sys 0.016s Metrics: {"bytes_written":4143687,"delete_count":0,"lbm_write_time_us":14624,"lbm_writes_lt_1ms":104,"reinsert_count":0,"update_count":505}
I20260812 06:17:32.240185 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling LogGCOp(4643b06ec4c047f2be7c7709d8b794ca): free 12017995 bytes of WAL
I20260812 06:17:32.240617 29770 log_reader.cc:385] T 4643b06ec4c047f2be7c7709d8b794ca: removed 1 log segments from log reader
I20260812 06:17:32.240736 29770 log.cc:1079] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/4643b06ec4c047f2be7c7709d8b794ca/wal-000000013 (ops 62-66)
I20260812 06:17:32.245409 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: LogGCOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.005s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:32.246088 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=2.188937
I20260812 06:17:32.270793 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.024s	user 0.018s	sys 0.006s Metrics: {"bytes_written":3774459,"delete_count":0,"lbm_write_time_us":8999,"lbm_writes_lt_1ms":95,"reinsert_count":0,"update_count":460}
I20260812 06:17:32.272100 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling MajorDeltaCompactionOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=1.000000
I20260812 06:17:32.669345 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: MajorDeltaCompactionOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.397s	user 0.280s	sys 0.112s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32856956,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":711,"lbm_read_time_us":36456,"lbm_reads_lt_1ms":775,"lbm_write_time_us":70697,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":15360,"thread_start_us":609,"threads_started":7,"update_count":3500}
I20260812 06:17:32.670080 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling UndoDeltaBlockGCOp(4643b06ec4c047f2be7c7709d8b794ca): 473 bytes on disk
I20260812 06:17:32.670671 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: UndoDeltaBlockGCOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":119,"lbm_reads_lt_1ms":4}
I20260812 06:17:32.671370 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=18.063937
I20260812 06:17:32.730650 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.059s	user 0.041s	sys 0.018s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":26962,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:32.731107 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=2.188937
I20260812 06:17:32.743674 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.012s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5038,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.744088 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling MajorDeltaCompactionOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=1.000000
I20260812 06:17:32.911928 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: MajorDeltaCompactionOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.168s	user 0.142s	sys 0.024s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28754209,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":462,"lbm_read_time_us":12056,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34567,"lbm_writes_lt_1ms":643,"mutex_wait_us":2,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":3000}
I20260812 06:17:32.912638 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=14.095187
I20260812 06:17:32.955830 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.043s	user 0.020s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19440,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:32.956470 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=2.188937
I20260812 06:17:32.971323 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.015s	user 0.004s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5674,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.971767 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling MajorDeltaCompactionOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=1.000000
I20260812 06:17:33.138504 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: MajorDeltaCompactionOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.167s	user 0.116s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24651793,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1333,"lbm_read_time_us":11105,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31076,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16896,"update_count":2500}
I20260812 06:17:33.139216 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=14.095187
I20260812 06:17:33.197021 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.058s	user 0.025s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23169,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:33.197745 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling MajorDeltaCompactionOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=1.000000
I20260812 06:17:33.345719 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: MajorDeltaCompactionOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.148s	user 0.099s	sys 0.048s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20549263,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":371,"lbm_read_time_us":10066,"lbm_reads_lt_1ms":463,"lbm_write_time_us":23175,"lbm_writes_lt_1ms":443,"mutex_wait_us":46,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17280,"update_count":2000}
I20260812 06:17:33.346532 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=14.095187
I20260812 06:17:33.396147 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.049s	user 0.031s	sys 0.017s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22115,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:33.396684 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=2.188937
I20260812 06:17:33.423924 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.027s	user 0.004s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5601,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":500}
I20260812 06:17:33.424510 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling MajorDeltaCompactionOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=1.000000
I20260812 06:17:33.593318 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: MajorDeltaCompactionOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.169s	user 0.084s	sys 0.084s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24651794,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":239,"lbm_read_time_us":12863,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27036,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:17:33.594131 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=14.095187
I20260812 06:17:33.643288 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.049s	user 0.024s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21407,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:33.644109 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=2.188937
I20260812 06:17:33.660830 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.017s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5734,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.661432 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling MajorDeltaCompactionOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=1.000000
I20260812 06:17:33.819077 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: MajorDeltaCompactionOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.157s	user 0.126s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24651794,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":128,"lbm_read_time_us":9777,"lbm_reads_lt_1ms":564,"lbm_write_time_us":32427,"lbm_writes_lt_1ms":543,"mutex_wait_us":31,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":26112,"update_count":2500}
I20260812 06:17:33.819650 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=14.095187
I20260812 06:17:33.869211 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.049s	user 0.035s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20340,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:33.869869 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=2.188937
I20260812 06:17:33.884618 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5754,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.885397 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushMRSOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=1.000000
I20260812 06:17:33.920361 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushMRSOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.035s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":222,"dirs.run_wall_time_us":1405,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1845,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:33.921037 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling LogGCOp(4643b06ec4c047f2be7c7709d8b794ca): free 121006394 bytes of WAL
I20260812 06:17:33.921267 29770 log_reader.cc:385] T 4643b06ec4c047f2be7c7709d8b794ca: removed 12 log segments from log reader
I20260812 06:17:33.921314 29770 log.cc:1079] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/4643b06ec4c047f2be7c7709d8b794ca/wal-000000014 (ops 67-71)
I20260812 06:17:33.921365 29770 log.cc:1079] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/4643b06ec4c047f2be7c7709d8b794ca/wal-000000015 (ops 72-76)
I20260812 06:17:33.921411 29770 log.cc:1079] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/4643b06ec4c047f2be7c7709d8b794ca/wal-000000016 (ops 77-80)
I20260812 06:17:33.921485 29770 log.cc:1079] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/4643b06ec4c047f2be7c7709d8b794ca/wal-000000017 (ops 81-85)
I20260812 06:17:33.921516 29770 log.cc:1079] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/4643b06ec4c047f2be7c7709d8b794ca/wal-000000018 (ops 86-90)
I20260812 06:17:33.921555 29770 log.cc:1079] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/4643b06ec4c047f2be7c7709d8b794ca/wal-000000019 (ops 91-95)
I20260812 06:17:33.921594 29770 log.cc:1079] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/4643b06ec4c047f2be7c7709d8b794ca/wal-000000020 (ops 96-100)
I20260812 06:17:33.921633 29770 log.cc:1079] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/4643b06ec4c047f2be7c7709d8b794ca/wal-000000021 (ops 101-105)
I20260812 06:17:33.921670 29770 log.cc:1079] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/4643b06ec4c047f2be7c7709d8b794ca/wal-000000022 (ops 106-110)
I20260812 06:17:33.921710 29770 log.cc:1079] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/4643b06ec4c047f2be7c7709d8b794ca/wal-000000023 (ops 111-115)
I20260812 06:17:33.921746 29770 log.cc:1079] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/4643b06ec4c047f2be7c7709d8b794ca/wal-000000024 (ops 116-120)
I20260812 06:17:33.921784 29770 log.cc:1079] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/4643b06ec4c047f2be7c7709d8b794ca/wal-000000025 (ops 121-125)
I20260812 06:17:33.949368 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: LogGCOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:17:33.949885 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling UndoDeltaBlockGCOp(4643b06ec4c047f2be7c7709d8b794ca): 493 bytes on disk
I20260812 06:17:33.950637 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: UndoDeltaBlockGCOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:17:33.951156 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=6.157687
I20260812 06:17:33.981793 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.030s	user 0.020s	sys 0.007s Metrics: {"bytes_written":7712789,"delete_count":0,"lbm_write_time_us":8204,"lbm_writes_lt_1ms":191,"reinsert_count":0,"update_count":940}
I20260812 06:17:33.982252 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling MajorDeltaCompactionOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=1.000000
I20260812 06:17:34.218051 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: MajorDeltaCompactionOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.236s	user 0.139s	sys 0.089s Metrics: {"cfile_cache_miss":721,"cfile_cache_miss_bytes":32364448,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":370,"lbm_read_time_us":17997,"lbm_reads_lt_1ms":753,"lbm_write_time_us":38356,"lbm_writes_lt_1ms":731,"mutex_wait_us":42,"peak_mem_usage":86436240,"reinsert_count":0,"spinlock_wait_cycles":3584,"thread_start_us":86,"threads_started":1,"update_count":3440}
I20260812 06:17:34.218828 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=19.056125
I20260812 06:17:34.285094 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.066s	user 0.048s	sys 0.014s Metrics: {"bytes_written":21004606,"delete_count":0,"lbm_write_time_us":28964,"lbm_writes_lt_1ms":515,"reinsert_count":0,"update_count":2560}
I20260812 06:17:34.285561 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=2.188937
I20260812 06:17:34.296366 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3994,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:34.296931 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling MajorDeltaCompactionOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=1.000000
I20260812 06:17:34.551187 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: MajorDeltaCompactionOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.254s	user 0.168s	sys 0.080s Metrics: {"cfile_cache_miss":644,"cfile_cache_miss_bytes":29246498,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":165,"lbm_read_time_us":15813,"lbm_reads_lt_1ms":684,"lbm_write_time_us":41408,"lbm_writes_lt_1ms":655,"mutex_wait_us":45,"peak_mem_usage":77075276,"reinsert_count":0,"spinlock_wait_cycles":8192,"update_count":3060}
I20260812 06:17:34.551970 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=18.063937
I20260812 06:17:34.626525 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.074s	user 0.032s	sys 0.032s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":29145,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:34.627061 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=2.188937
I20260812 06:17:34.637346 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3877,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:34.638128 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling MajorDeltaCompactionOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=1.000000
I20260812 06:17:34.846575 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: MajorDeltaCompactionOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.208s	user 0.125s	sys 0.076s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28754209,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":673,"lbm_read_time_us":12940,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33684,"lbm_writes_lt_1ms":643,"mutex_wait_us":302,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":3000}
I20260812 06:17:34.847445 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=16.079562
I20260812 06:17:34.897917 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.050s	user 0.021s	sys 0.022s Metrics: {"bytes_written":17681653,"delete_count":0,"lbm_write_time_us":20159,"lbm_writes_lt_1ms":434,"reinsert_count":0,"update_count":2155}
I20260812 06:17:34.898545 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=2.188937
I20260812 06:17:34.909026 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.010s	user 0.006s	sys 0.001s Metrics: {"bytes_written":3241134,"delete_count":0,"lbm_write_time_us":3336,"lbm_writes_lt_1ms":82,"reinsert_count":0,"update_count":395}
I20260812 06:17:34.909521 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=2.188937
I20260812 06:17:34.919250 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3702,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:34.919709 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling MajorDeltaCompactionOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=1.000000
I20260812 06:17:35.127563 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: MajorDeltaCompactionOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.208s	user 0.136s	sys 0.059s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28754297,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":870,"lbm_read_time_us":14420,"lbm_reads_lt_1ms":673,"lbm_write_time_us":32615,"lbm_writes_lt_1ms":643,"mutex_wait_us":66,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6272,"update_count":3000}
I20260812 06:17:35.128199 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=18.063937
I20260812 06:17:35.195919 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.068s	user 0.043s	sys 0.012s Metrics: {"bytes_written":20512314,"delete_count":0,"lbm_write_time_us":25779,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:35.196394 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=2.188937
I20260812 06:17:35.207733 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.011s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4148,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.208299 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling MajorDeltaCompactionOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=1.000000
I20260812 06:17:35.427610 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: MajorDeltaCompactionOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.219s	user 0.153s	sys 0.060s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28754206,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":448,"lbm_read_time_us":14629,"lbm_reads_lt_1ms":672,"lbm_write_time_us":39490,"lbm_writes_lt_1ms":643,"mutex_wait_us":88,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":3000}
I20260812 06:17:35.428422 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=16.079562
I20260812 06:17:35.493949 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.065s	user 0.027s	sys 0.024s Metrics: {"bytes_written":17681651,"delete_count":0,"lbm_write_time_us":25308,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":433,"reinsert_count":0,"update_count":2155}
I20260812 06:17:35.494464 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=5.165500
I20260812 06:17:35.512238 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.018s	user 0.003s	sys 0.013s Metrics: {"bytes_written":6933337,"delete_count":0,"lbm_write_time_us":7497,"lbm_writes_lt_1ms":172,"reinsert_count":0,"update_count":845}
I20260812 06:17:35.512794 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushMRSOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=1.000000
I20260812 06:17:35.542680 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushMRSOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.030s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":186,"dirs.run_wall_time_us":1394,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1960,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:35.543551 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling LogGCOp(4643b06ec4c047f2be7c7709d8b794ca): free 133477760 bytes of WAL
I20260812 06:17:35.543794 29770 log_reader.cc:385] T 4643b06ec4c047f2be7c7709d8b794ca: removed 13 log segments from log reader
I20260812 06:17:35.543857 29770 log.cc:1079] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/4643b06ec4c047f2be7c7709d8b794ca/wal-000000026 (ops 126-130)
I20260812 06:17:35.543903 29770 log.cc:1079] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/4643b06ec4c047f2be7c7709d8b794ca/wal-000000027 (ops 131-135)
I20260812 06:17:35.543943 29770 log.cc:1079] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/4643b06ec4c047f2be7c7709d8b794ca/wal-000000028 (ops 136-140)
I20260812 06:17:35.543979 29770 log.cc:1079] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/4643b06ec4c047f2be7c7709d8b794ca/wal-000000029 (ops 141-145)
I20260812 06:17:35.544016 29770 log.cc:1079] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/4643b06ec4c047f2be7c7709d8b794ca/wal-000000030 (ops 146-150)
I20260812 06:17:35.544056 29770 log.cc:1079] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/4643b06ec4c047f2be7c7709d8b794ca/wal-000000031 (ops 151-155)
I20260812 06:17:35.544097 29770 log.cc:1079] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/4643b06ec4c047f2be7c7709d8b794ca/wal-000000032 (ops 156-160)
I20260812 06:17:35.544139 29770 log.cc:1079] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/4643b06ec4c047f2be7c7709d8b794ca/wal-000000033 (ops 161-165)
I20260812 06:17:35.544178 29770 log.cc:1079] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/4643b06ec4c047f2be7c7709d8b794ca/wal-000000034 (ops 166-170)
I20260812 06:17:35.544217 29770 log.cc:1079] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/4643b06ec4c047f2be7c7709d8b794ca/wal-000000035 (ops 171-175)
I20260812 06:17:35.544257 29770 log.cc:1079] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/4643b06ec4c047f2be7c7709d8b794ca/wal-000000036 (ops 176-180)
I20260812 06:17:35.544296 29770 log.cc:1079] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/4643b06ec4c047f2be7c7709d8b794ca/wal-000000037 (ops 181-185)
I20260812 06:17:35.544335 29770 log.cc:1079] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/4643b06ec4c047f2be7c7709d8b794ca/wal-000000038 (ops 186-190)
I20260812 06:17:35.575910 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: LogGCOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.032s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:17:35.576387 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=5.165500
I20260812 06:17:35.597391 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.021s	user 0.018s	sys 0.000s Metrics: {"bytes_written":6687183,"delete_count":0,"lbm_write_time_us":8745,"lbm_writes_lt_1ms":166,"reinsert_count":0,"update_count":815}
I20260812 06:17:35.597877 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling LogGCOp(4643b06ec4c047f2be7c7709d8b794ca): free 11564901 bytes of WAL
I20260812 06:17:35.598156 29770 log_reader.cc:385] T 4643b06ec4c047f2be7c7709d8b794ca: removed 1 log segments from log reader
I20260812 06:17:35.598229 29770 log.cc:1079] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: Deleting log segment in path: /tmp/dist-test-task1WiHyQ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515443825327-29432-0/minicluster-data/ts-0-root/wals/4643b06ec4c047f2be7c7709d8b794ca/wal-000000039 (ops 191-194)
I20260812 06:17:35.601531 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: LogGCOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:35.602451 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=1.000000
I20260812 06:17:35.615602 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: FlushDeltaMemStoresOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.013s	user 0.006s	sys 0.001s Metrics: {"bytes_written":1518077,"delete_count":0,"lbm_write_time_us":2743,"lbm_writes_lt_1ms":40,"reinsert_count":0,"update_count":185}
I20260812 06:17:35.616070 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling UndoDeltaBlockGCOp(4643b06ec4c047f2be7c7709d8b794ca): 492 bytes on disk
I20260812 06:17:35.616454 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: UndoDeltaBlockGCOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:17:35.616950 29841 maintenance_manager.cc:419] P 92acd8c3a785416cb5a55474846a9634: Scheduling MajorDeltaCompactionOp(4643b06ec4c047f2be7c7709d8b794ca): perf score=1.000000
I20260812 06:17:35.725150 29432 heavy-update-compaction-itest.cc:229] Time spent updating: real 6.238s	user 2.293s	sys 0.195s
I20260812 06:17:35.823800 29432 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.098s	user 0.001s	sys 0.000s
I20260812 06:17:35.824358 29432 tablet_server.cc:179] TabletServer@127.28.190.1:0 shutting down...
I20260812 06:17:35.838811 29770 maintenance_manager.cc:643] P 92acd8c3a785416cb5a55474846a9634: MajorDeltaCompactionOp(4643b06ec4c047f2be7c7709d8b794ca) complete. Timing: real 0.222s	user 0.148s	sys 0.073s Metrics: {"cfile_cache_miss":834,"cfile_cache_miss_bytes":36959214,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":813,"lbm_read_time_us":16760,"lbm_reads_lt_1ms":862,"lbm_write_time_us":37800,"lbm_writes_lt_1ms":843,"mutex_wait_us":126,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":4480,"thread_start_us":71,"threads_started":1,"update_count":4000}
I20260812 06:17:35.839977 29432 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:35.840269 29432 tablet_replica.cc:333] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634: stopping tablet replica
I20260812 06:17:35.840456 29432 raft_consensus.cc:2243] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:35.840684 29432 raft_consensus.cc:2272] T 4643b06ec4c047f2be7c7709d8b794ca P 92acd8c3a785416cb5a55474846a9634 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:35.846325 29432 tablet_server.cc:196] TabletServer@127.28.190.1:0 shutdown complete.
I20260812 06:17:35.909817 29432 master.cc:562] Master@127.28.190.62:42445 shutting down...
I20260812 06:17:35.914011 29432 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 9173b1cf56884bc6b15d421ddab032d9 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:35.914264 29432 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 9173b1cf56884bc6b15d421ddab032d9 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:35.914357 29432 tablet_replica.cc:333] T 00000000000000000000000000000000 P 9173b1cf56884bc6b15d421ddab032d9: stopping tablet replica
I20260812 06:17:35.927158 29432 master.cc:584] Master@127.28.190.62:42445 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (6824 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (12175 ms total)

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