[==========] 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:40.738626 32641 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.31.224.126:34547
I20260812 06:17:40.739737 32641 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:40.740392 32641 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:40.746881 32647 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:40.746908 32651 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:40.747174 32646 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:40.747241 32641 server_base.cc:1061] running on GCE node
I20260812 06:17:40.747741 32641 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:40.747866 32641 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:40.747931 32641 hybrid_clock.cc:648] HybridClock initialized: now 1786515460747928 us; error 0 us; skew 500 ppm
I20260812 06:17:40.749946 32641 webserver.cc:533] Webserver started at http://127.31.224.126:33489/ using document root <none> and password file <none>
I20260812 06:17:40.750605 32641 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:40.750696 32641 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:40.750954 32641 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:40.752671 32641 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/master-0-root/instance:
uuid: "50900254d6624d11914915540cdeea1c"
format_stamp: "Formatted at 2026-08-12 06:17:40 on dist-test-slave-9jjr"
I20260812 06:17:40.756490 32641 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:17:40.758957 32656 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:40.759974 32641 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:17:40.760119 32641 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/master-0-root
uuid: "50900254d6624d11914915540cdeea1c"
format_stamp: "Formatted at 2026-08-12 06:17:40 on dist-test-slave-9jjr"
I20260812 06:17:40.760237 32641 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-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:40.777684 32641 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:40.778543 32641 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:40.778863 32641 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:40.787611 32641 rpc_server.cc:307] RPC server started. Bound to: 127.31.224.126:34547
I20260812 06:17:40.787648 32722 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.31.224.126:34547 every 8 connection(s)
I20260812 06:17:40.790187 32723 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:40.796232 32723 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 50900254d6624d11914915540cdeea1c: Bootstrap starting.
I20260812 06:17:40.798830 32723 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 50900254d6624d11914915540cdeea1c: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:40.800151 32723 log.cc:826] T 00000000000000000000000000000000 P 50900254d6624d11914915540cdeea1c: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:40.802488 32723 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 50900254d6624d11914915540cdeea1c: No bootstrap required, opened a new log
I20260812 06:17:40.805598 32723 raft_consensus.cc:359] T 00000000000000000000000000000000 P 50900254d6624d11914915540cdeea1c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "50900254d6624d11914915540cdeea1c" member_type: VOTER }
I20260812 06:17:40.805809 32723 raft_consensus.cc:385] T 00000000000000000000000000000000 P 50900254d6624d11914915540cdeea1c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:40.805863 32723 raft_consensus.cc:740] T 00000000000000000000000000000000 P 50900254d6624d11914915540cdeea1c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 50900254d6624d11914915540cdeea1c, State: Initialized, Role: FOLLOWER
I20260812 06:17:40.806516 32723 consensus_queue.cc:260] T 00000000000000000000000000000000 P 50900254d6624d11914915540cdeea1c [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: "50900254d6624d11914915540cdeea1c" member_type: VOTER }
I20260812 06:17:40.806669 32723 raft_consensus.cc:399] T 00000000000000000000000000000000 P 50900254d6624d11914915540cdeea1c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:40.806721 32723 raft_consensus.cc:493] T 00000000000000000000000000000000 P 50900254d6624d11914915540cdeea1c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:40.806818 32723 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 50900254d6624d11914915540cdeea1c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:40.807729 32723 raft_consensus.cc:515] T 00000000000000000000000000000000 P 50900254d6624d11914915540cdeea1c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "50900254d6624d11914915540cdeea1c" member_type: VOTER }
I20260812 06:17:40.808178 32723 leader_election.cc:304] T 00000000000000000000000000000000 P 50900254d6624d11914915540cdeea1c [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: 50900254d6624d11914915540cdeea1c; no voters: 
I20260812 06:17:40.808487 32723 leader_election.cc:290] T 00000000000000000000000000000000 P 50900254d6624d11914915540cdeea1c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:40.808815 32726 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 50900254d6624d11914915540cdeea1c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:40.809082 32726 raft_consensus.cc:697] T 00000000000000000000000000000000 P 50900254d6624d11914915540cdeea1c [term 1 LEADER]: Becoming Leader. State: Replica: 50900254d6624d11914915540cdeea1c, State: Running, Role: LEADER
I20260812 06:17:40.809513 32726 consensus_queue.cc:237] T 00000000000000000000000000000000 P 50900254d6624d11914915540cdeea1c [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: "50900254d6624d11914915540cdeea1c" member_type: VOTER }
I20260812 06:17:40.809577 32723 sys_catalog.cc:565] T 00000000000000000000000000000000 P 50900254d6624d11914915540cdeea1c [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:40.811841 32727 sys_catalog.cc:455] T 00000000000000000000000000000000 P 50900254d6624d11914915540cdeea1c [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "50900254d6624d11914915540cdeea1c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "50900254d6624d11914915540cdeea1c" member_type: VOTER } }
I20260812 06:17:40.812022 32727 sys_catalog.cc:458] T 00000000000000000000000000000000 P 50900254d6624d11914915540cdeea1c [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:40.811841 32729 sys_catalog.cc:455] T 00000000000000000000000000000000 P 50900254d6624d11914915540cdeea1c [sys.catalog]: SysCatalogTable state changed. Reason: New leader 50900254d6624d11914915540cdeea1c. Latest consensus state: current_term: 1 leader_uuid: "50900254d6624d11914915540cdeea1c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "50900254d6624d11914915540cdeea1c" member_type: VOTER } }
I20260812 06:17:40.812288 32729 sys_catalog.cc:458] T 00000000000000000000000000000000 P 50900254d6624d11914915540cdeea1c [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:40.812448 32641 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:17:40.815699 32742 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 50900254d6624d11914915540cdeea1c: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:17:40.815822 32742 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:17:40.815936 32741 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:40.816948 32741 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:40.822367 32741 catalog_manager.cc:1383] Generated new cluster ID: 39f72be8ba114e8e8bd1cdc5d8a1f314
I20260812 06:17:40.822463 32741 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:40.832610 32741 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:40.833868 32741 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:40.840920 32741 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 50900254d6624d11914915540cdeea1c: Generated new TSK 0
I20260812 06:17:40.841750 32741 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:40.845103 32641 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:40.848078 32746 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:40.848227 32641 server_base.cc:1061] running on GCE node
W20260812 06:17:40.848143 32750 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:40.848400 32748 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:40.848623 32641 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:40.848690 32641 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:40.848712 32641 hybrid_clock.cc:648] HybridClock initialized: now 1786515460848712 us; error 0 us; skew 500 ppm
I20260812 06:17:40.849761 32641 webserver.cc:533] Webserver started at http://127.31.224.65:38989/ using document root <none> and password file <none>
I20260812 06:17:40.849948 32641 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:40.850008 32641 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:40.850087 32641 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:40.850581 32641 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root/instance:
uuid: "c141d67065e348b9b80c7e3217836177"
format_stamp: "Formatted at 2026-08-12 06:17:40 on dist-test-slave-9jjr"
I20260812 06:17:40.852524 32641 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:40.853677 32760 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:40.853974 32641 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:40.854044 32641 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root
uuid: "c141d67065e348b9b80c7e3217836177"
format_stamp: "Formatted at 2026-08-12 06:17:40 on dist-test-slave-9jjr"
I20260812 06:17:40.854151 32641 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-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:40.869668 32641 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:40.870246 32641 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:40.870836 32641 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:40.871718 32641 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:40.871774 32641 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:40.871968 32641 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:40.872040 32641 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:40.879310 32641 rpc_server.cc:307] RPC server started. Bound to: 127.31.224.65:46141
I20260812 06:17:40.879340   365 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.31.224.65:46141 every 8 connection(s)
I20260812 06:17:40.890945   368 heartbeater.cc:344] Connected to a master server at 127.31.224.126:34547
I20260812 06:17:40.891306   368 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:40.891801   368 heartbeater.cc:507] Master 127.31.224.126:34547 requested a full tablet report, sending...
I20260812 06:17:40.893357 32678 ts_manager.cc:194] Registered new tserver with Master: c141d67065e348b9b80c7e3217836177 (127.31.224.65:46141)
I20260812 06:17:40.893613 32641 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013572682s
I20260812 06:17:40.895026 32678 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:57208
I20260812 06:17:40.904281 32678 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:57218:
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:40.920708   324 tablet_service.cc:1511] Processing CreateTablet for tablet 7b1290774aed4fd099345e6e68efc03c (DEFAULT_TABLE table=heavy-update-compaction-test [id=ce9e477e185a4e618f2fa06302618d18]), partition=
I20260812 06:17:40.921176   324 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 7b1290774aed4fd099345e6e68efc03c. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:40.923843   385 tablet_bootstrap.cc:492] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Bootstrap starting.
I20260812 06:17:40.924846   385 tablet_bootstrap.cc:654] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:40.925997   385 tablet_bootstrap.cc:492] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: No bootstrap required, opened a new log
I20260812 06:17:40.926162   385 ts_tablet_manager.cc:1403] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:40.926658   385 raft_consensus.cc:359] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c141d67065e348b9b80c7e3217836177" member_type: VOTER last_known_addr { host: "127.31.224.65" port: 46141 } }
I20260812 06:17:40.926793   385 raft_consensus.cc:385] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:40.926887   385 raft_consensus.cc:740] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c141d67065e348b9b80c7e3217836177, State: Initialized, Role: FOLLOWER
I20260812 06:17:40.927080   385 consensus_queue.cc:260] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177 [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: "c141d67065e348b9b80c7e3217836177" member_type: VOTER last_known_addr { host: "127.31.224.65" port: 46141 } }
I20260812 06:17:40.927249   385 raft_consensus.cc:399] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:40.927330   385 raft_consensus.cc:493] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:40.927402   385 raft_consensus.cc:3060] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:40.928170   385 raft_consensus.cc:515] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c141d67065e348b9b80c7e3217836177" member_type: VOTER last_known_addr { host: "127.31.224.65" port: 46141 } }
I20260812 06:17:40.928334   385 leader_election.cc:304] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177 [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: c141d67065e348b9b80c7e3217836177; no voters: 
I20260812 06:17:40.928570   385 leader_election.cc:290] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:40.928678   387 raft_consensus.cc:2804] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:40.928941   387 raft_consensus.cc:697] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177 [term 1 LEADER]: Becoming Leader. State: Replica: c141d67065e348b9b80c7e3217836177, State: Running, Role: LEADER
I20260812 06:17:40.929177   368 heartbeater.cc:499] Master 127.31.224.126:34547 was elected leader, sending a full tablet report...
I20260812 06:17:40.929143   387 consensus_queue.cc:237] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177 [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: "c141d67065e348b9b80c7e3217836177" member_type: VOTER last_known_addr { host: "127.31.224.65" port: 46141 } }
I20260812 06:17:40.928947   385 ts_tablet_manager.cc:1434] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Time spent starting tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:40.932438 32678 catalog_manager.cc:5719] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177 reported cstate change: term changed from 0 to 1, leader changed from <none> to c141d67065e348b9b80c7e3217836177 (127.31.224.65). New cstate: current_term: 1 leader_uuid: "c141d67065e348b9b80c7e3217836177" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c141d67065e348b9b80c7e3217836177" member_type: VOTER last_known_addr { host: "127.31.224.65" port: 46141 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:40.998885 32641 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.059s	user 0.022s	sys 0.005s
I20260812 06:17:41.130723   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushMRSOp(7b1290774aed4fd099345e6e68efc03c): perf score=15.086190
I20260812 06:17:41.290817 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushMRSOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.160s	user 0.118s	sys 0.036s Metrics: {"bytes_written":11897249,"cfile_init":1,"compiler_manager_pool.queue_time_us":247,"delete_count":0,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":213,"dirs.run_wall_time_us":732,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39551,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":140,"threads_started":1,"update_count":1450}
I20260812 06:17:41.292021   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling LogGCOp(7b1290774aed4fd099345e6e68efc03c): free 20743880 bytes of WAL
I20260812 06:17:41.292412 32766 log_reader.cc:385] T 7b1290774aed4fd099345e6e68efc03c: removed 2 log segments from log reader
I20260812 06:17:41.292500 32766 log.cc:1079] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/7b1290774aed4fd099345e6e68efc03c/wal-000000001 (ops 1-6)
I20260812 06:17:41.292626 32766 log.cc:1079] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/7b1290774aed4fd099345e6e68efc03c/wal-000000002 (ops 7-11)
I20260812 06:17:41.298257 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: LogGCOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.006s	user 0.000s	sys 0.006s Metrics: {}
I20260812 06:17:41.298930   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=2.188937
I20260812 06:17:41.315511 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.016s	user 0.005s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6251,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.315989   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c): perf score=1.000000
I20260812 06:17:41.450173 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.134s	user 0.114s	sys 0.020s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262036,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1276,"lbm_read_time_us":9885,"lbm_reads_lt_1ms":454,"lbm_write_time_us":26947,"lbm_writes_lt_1ms":433,"mutex_wait_us":163,"peak_mem_usage":49238594,"reinsert_count":0,"thread_start_us":367,"threads_started":5,"update_count":1950}
I20260812 06:17:41.450850   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling UndoDeltaBlockGCOp(7b1290774aed4fd099345e6e68efc03c): 12719217 bytes on disk
I20260812 06:17:41.451393 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: UndoDeltaBlockGCOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4}
I20260812 06:17:41.451972   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=10.126437
I20260812 06:17:41.502492 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.050s	user 0.020s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19525,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:41.503037   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=2.188937
I20260812 06:17:41.514992 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4407,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.515549   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c): perf score=1.000000
I20260812 06:17:41.645004 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.129s	user 0.092s	sys 0.037s 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":132,"lbm_read_time_us":9901,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25733,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":75136,"update_count":2000}
I20260812 06:17:41.645617   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=10.126437
I20260812 06:17:41.692922 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.047s	user 0.019s	sys 0.015s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16084,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":499584,"update_count":1500}
I20260812 06:17:41.693452   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=2.188937
I20260812 06:17:41.705281 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4230,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.705749   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c): perf score=1.000000
I20260812 06:17:41.837013 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.131s	user 0.107s	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":166,"lbm_read_time_us":10267,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26472,"lbm_writes_lt_1ms":443,"mutex_wait_us":60,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:41.837639   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=10.126437
I20260812 06:17:41.885273 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.047s	user 0.025s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17299,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:41.885883   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=2.188937
I20260812 06:17:41.897264 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4203,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.897791   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c): perf score=1.000000
I20260812 06:17:42.049015 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.151s	user 0.096s	sys 0.052s 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":352,"lbm_read_time_us":12588,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24788,"lbm_writes_lt_1ms":443,"mutex_wait_us":3,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":2000}
I20260812 06:17:42.049634   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=10.126437
I20260812 06:17:42.094902 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.045s	user 0.029s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16893,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:42.095450   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=2.188937
I20260812 06:17:42.106887 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4236,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.107461   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c): perf score=1.000000
I20260812 06:17:42.234706 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.127s	user 0.104s	sys 0.022s 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":1190,"lbm_read_time_us":9433,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23306,"lbm_writes_lt_1ms":443,"mutex_wait_us":386,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":2000}
I20260812 06:17:42.235257   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=10.126437
I20260812 06:17:42.278357 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.043s	user 0.014s	sys 0.029s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19899,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:42.278992   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=2.188937
I20260812 06:17:42.294368 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.015s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5523,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.295015   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c): perf score=1.000000
I20260812 06:17:42.422155 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.127s	user 0.102s	sys 0.025s 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":1359,"lbm_read_time_us":9647,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23813,"lbm_writes_lt_1ms":443,"mutex_wait_us":269,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2000}
I20260812 06:17:42.422677   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=10.126437
I20260812 06:17:42.477461 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.055s	user 0.024s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15648,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:42.478108   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=2.188937
I20260812 06:17:42.494701 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.016s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6257,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.495394   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c): perf score=1.000000
I20260812 06:17:42.652525 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.157s	user 0.112s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":854,"lbm_read_time_us":12329,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26315,"lbm_writes_lt_1ms":443,"mutex_wait_us":393,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":190848,"update_count":2000}
I20260812 06:17:42.653317   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=10.126437
I20260812 06:17:42.702853 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.049s	user 0.018s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17076,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:42.703498   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=2.188937
I20260812 06:17:42.716295 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.013s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4340,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.716964   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushMRSOp(7b1290774aed4fd099345e6e68efc03c): perf score=1.000000
I20260812 06:17:42.753722 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushMRSOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.037s	user 0.035s	sys 0.000s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":76,"dirs.run_cpu_time_us":223,"dirs.run_wall_time_us":1449,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1699,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:42.754761   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling LogGCOp(7b1290774aed4fd099345e6e68efc03c): free 128867446 bytes of WAL
I20260812 06:17:42.755034 32766 log_reader.cc:385] T 7b1290774aed4fd099345e6e68efc03c: removed 13 log segments from log reader
I20260812 06:17:42.755084 32766 log.cc:1079] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/7b1290774aed4fd099345e6e68efc03c/wal-000000003 (ops 12-16)
I20260812 06:17:42.755113 32766 log.cc:1079] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/7b1290774aed4fd099345e6e68efc03c/wal-000000004 (ops 17-20)
I20260812 06:17:42.755151 32766 log.cc:1079] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/7b1290774aed4fd099345e6e68efc03c/wal-000000005 (ops 21-25)
I20260812 06:17:42.755193 32766 log.cc:1079] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/7b1290774aed4fd099345e6e68efc03c/wal-000000006 (ops 26-30)
I20260812 06:17:42.755221 32766 log.cc:1079] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/7b1290774aed4fd099345e6e68efc03c/wal-000000007 (ops 31-34)
I20260812 06:17:42.755273 32766 log.cc:1079] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/7b1290774aed4fd099345e6e68efc03c/wal-000000008 (ops 35-39)
I20260812 06:17:42.755312 32766 log.cc:1079] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/7b1290774aed4fd099345e6e68efc03c/wal-000000009 (ops 40-44)
I20260812 06:17:42.755355 32766 log.cc:1079] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/7b1290774aed4fd099345e6e68efc03c/wal-000000010 (ops 45-48)
I20260812 06:17:42.755395 32766 log.cc:1079] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/7b1290774aed4fd099345e6e68efc03c/wal-000000011 (ops 49-53)
I20260812 06:17:42.755434 32766 log.cc:1079] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/7b1290774aed4fd099345e6e68efc03c/wal-000000012 (ops 54-58)
I20260812 06:17:42.755471 32766 log.cc:1079] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/7b1290774aed4fd099345e6e68efc03c/wal-000000013 (ops 59-63)
I20260812 06:17:42.755507 32766 log.cc:1079] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/7b1290774aed4fd099345e6e68efc03c/wal-000000014 (ops 64-68)
I20260812 06:17:42.755543 32766 log.cc:1079] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/7b1290774aed4fd099345e6e68efc03c/wal-000000015 (ops 69-73)
I20260812 06:17:42.784955 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: LogGCOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.030s	user 0.004s	sys 0.024s Metrics: {}
I20260812 06:17:42.785609   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling UndoDeltaBlockGCOp(7b1290774aed4fd099345e6e68efc03c): 482 bytes on disk
I20260812 06:17:42.786281 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: UndoDeltaBlockGCOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4}
I20260812 06:17:42.786849   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=5.165500
I20260812 06:17:42.816640 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.030s	user 0.015s	sys 0.012s Metrics: {"bytes_written":6400017,"delete_count":0,"lbm_write_time_us":8059,"lbm_writes_lt_1ms":159,"reinsert_count":0,"update_count":780}
I20260812 06:17:42.817365   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=1.000000
I20260812 06:17:42.826611 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.009s	user 0.009s	sys 0.000s Metrics: {"bytes_written":1805252,"delete_count":0,"lbm_write_time_us":3241,"lbm_writes_lt_1ms":47,"reinsert_count":0,"update_count":220}
I20260812 06:17:42.827116   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c): perf score=1.000000
I20260812 06:17:43.035144 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.208s	user 0.125s	sys 0.079s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877285,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1247,"lbm_read_time_us":16074,"lbm_reads_lt_1ms":674,"lbm_write_time_us":38337,"lbm_writes_lt_1ms":643,"mutex_wait_us":605,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6016,"thread_start_us":105,"threads_started":1,"update_count":3000}
I20260812 06:17:43.035836   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=11.118625
I20260812 06:17:43.073655 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.038s	user 0.026s	sys 0.009s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":16422,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:43.074308   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=2.188937
I20260812 06:17:43.089529 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5612,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:43.090058   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c): perf score=1.000000
I20260812 06:17:43.244637 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.154s	user 0.110s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672270,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":207,"lbm_read_time_us":9736,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26193,"lbm_writes_lt_1ms":443,"mutex_wait_us":40,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2000}
I20260812 06:17:43.245445   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=10.126437
I20260812 06:17:43.283993 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.038s	user 0.022s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15762,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:43.284457   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=2.188937
I20260812 06:17:43.295405 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4035,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:43.295938   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c): perf score=1.000000
I20260812 06:17:43.429001 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.133s	user 0.092s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1254,"lbm_read_time_us":9046,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26278,"lbm_writes_lt_1ms":443,"mutex_wait_us":392,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:17:43.429735   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=10.126437
I20260812 06:17:43.472291 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.042s	user 0.020s	sys 0.019s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17931,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:43.472908   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=2.188937
I20260812 06:17:43.490191 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.017s	user 0.010s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6506,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:43.490944   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c): perf score=1.000000
I20260812 06:17:43.612713 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.121s	user 0.105s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1362,"lbm_read_time_us":7748,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23685,"lbm_writes_lt_1ms":443,"mutex_wait_us":67,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15616,"update_count":2000}
I20260812 06:17:43.613492   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=10.126437
I20260812 06:17:43.660333 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.047s	user 0.026s	sys 0.018s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":18567,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:43.660959   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=2.188937
I20260812 06:17:43.672549 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4216,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:43.673301   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c): perf score=1.000000
I20260812 06:17:43.821460 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.148s	user 0.091s	sys 0.056s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":937,"lbm_read_time_us":10732,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28207,"lbm_writes_lt_1ms":443,"mutex_wait_us":385,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":2000}
I20260812 06:17:43.822029   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=10.126437
I20260812 06:17:43.863462 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.041s	user 0.024s	sys 0.015s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17916,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:43.863986   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=2.188937
I20260812 06:17:43.877559 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.013s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5266,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:43.878494   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c): perf score=1.000000
I20260812 06:17:44.012383 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.134s	user 0.100s	sys 0.032s 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":1427,"lbm_read_time_us":9213,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25408,"lbm_writes_lt_1ms":443,"mutex_wait_us":3,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13056,"update_count":2000}
I20260812 06:17:44.013139   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=10.126437
I20260812 06:17:44.048120 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.035s	user 0.013s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15259,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:44.048745   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=2.188937
I20260812 06:17:44.065150 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.016s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6286,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:44.065632   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c): perf score=1.000000
I20260812 06:17:44.197538 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.132s	user 0.102s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2239,"lbm_read_time_us":7757,"lbm_reads_lt_1ms":468,"lbm_write_time_us":25129,"lbm_writes_lt_1ms":443,"mutex_wait_us":925,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:17:44.198702   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=10.126437
I20260812 06:17:44.239614 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.041s	user 0.026s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16676,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:44.240180   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=2.188937
I20260812 06:17:44.251086 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4089,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:44.251700   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushMRSOp(7b1290774aed4fd099345e6e68efc03c): perf score=1.000000
I20260812 06:17:44.284221 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushMRSOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.032s	user 0.030s	sys 0.001s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":259,"dirs.run_wall_time_us":1465,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1630,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:44.284937   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling LogGCOp(7b1290774aed4fd099345e6e68efc03c): free 124710328 bytes of WAL
I20260812 06:17:44.285171 32766 log_reader.cc:385] T 7b1290774aed4fd099345e6e68efc03c: removed 12 log segments from log reader
I20260812 06:17:44.285215 32766 log.cc:1079] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/7b1290774aed4fd099345e6e68efc03c/wal-000000016 (ops 74-78)
I20260812 06:17:44.285244 32766 log.cc:1079] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/7b1290774aed4fd099345e6e68efc03c/wal-000000017 (ops 79-83)
I20260812 06:17:44.285300 32766 log.cc:1079] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/7b1290774aed4fd099345e6e68efc03c/wal-000000018 (ops 84-88)
I20260812 06:17:44.285346 32766 log.cc:1079] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/7b1290774aed4fd099345e6e68efc03c/wal-000000019 (ops 89-93)
I20260812 06:17:44.285387 32766 log.cc:1079] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/7b1290774aed4fd099345e6e68efc03c/wal-000000020 (ops 94-98)
I20260812 06:17:44.285452 32766 log.cc:1079] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/7b1290774aed4fd099345e6e68efc03c/wal-000000021 (ops 99-103)
I20260812 06:17:44.285485 32766 log.cc:1079] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/7b1290774aed4fd099345e6e68efc03c/wal-000000022 (ops 104-108)
I20260812 06:17:44.285519 32766 log.cc:1079] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/7b1290774aed4fd099345e6e68efc03c/wal-000000023 (ops 109-113)
I20260812 06:17:44.285578 32766 log.cc:1079] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/7b1290774aed4fd099345e6e68efc03c/wal-000000024 (ops 114-118)
I20260812 06:17:44.285617 32766 log.cc:1079] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/7b1290774aed4fd099345e6e68efc03c/wal-000000025 (ops 119-123)
I20260812 06:17:44.285656 32766 log.cc:1079] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/7b1290774aed4fd099345e6e68efc03c/wal-000000026 (ops 124-128)
I20260812 06:17:44.285697 32766 log.cc:1079] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/7b1290774aed4fd099345e6e68efc03c/wal-000000027 (ops 129-133)
I20260812 06:17:44.314908 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: LogGCOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.030s	user 0.002s	sys 0.027s Metrics: {}
I20260812 06:17:44.315526   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling UndoDeltaBlockGCOp(7b1290774aed4fd099345e6e68efc03c): 473 bytes on disk
I20260812 06:17:44.316037 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: UndoDeltaBlockGCOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:17:44.316653   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=3.181125
I20260812 06:17:44.329749 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.013s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4797,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:44.330440   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=2.188937
I20260812 06:17:44.341203 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3699,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:44.342043   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c): perf score=1.000000
I20260812 06:17:44.517338 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.175s	user 0.140s	sys 0.033s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877331,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":297,"lbm_read_time_us":12322,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35772,"lbm_writes_lt_1ms":643,"mutex_wait_us":22,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11392,"thread_start_us":90,"threads_started":1,"update_count":3000}
I20260812 06:17:44.518205   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=14.095187
I20260812 06:17:44.570883 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.052s	user 0.036s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21077,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:44.571519   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=2.188937
I20260812 06:17:44.587647 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.016s	user 0.009s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5924,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:44.589238   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c): perf score=1.000000
I20260812 06:17:44.750558 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.161s	user 0.108s	sys 0.053s 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":663,"lbm_read_time_us":11774,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30590,"lbm_writes_lt_1ms":543,"mutex_wait_us":299,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6272,"update_count":2500}
I20260812 06:17:44.751418   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=11.118625
I20260812 06:17:44.789940 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.038s	user 0.022s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16724,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:44.790778   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=2.188937
I20260812 06:17:44.806212 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.015s	user 0.012s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5199,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:44.806955   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c): perf score=1.000000
I20260812 06:17:44.966629 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.159s	user 0.111s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":686,"lbm_read_time_us":11344,"lbm_reads_lt_1ms":464,"lbm_write_time_us":28046,"lbm_writes_lt_1ms":443,"mutex_wait_us":87,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2000}
I20260812 06:17:44.967329   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=10.126437
I20260812 06:17:45.013847 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.046s	user 0.013s	sys 0.031s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":20459,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:17:45.014510   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=2.188937
I20260812 06:17:45.039531 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.025s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5830,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:45.040016   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=2.188937
I20260812 06:17:45.060489 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.020s	user 0.003s	sys 0.015s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4101,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:45.061268   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c): perf score=1.000000
I20260812 06:17:45.254218 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.193s	user 0.127s	sys 0.062s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774806,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":319,"lbm_read_time_us":12261,"lbm_reads_lt_1ms":573,"lbm_write_time_us":34478,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:17:45.254850   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=11.118625
I20260812 06:17:45.310041 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.055s	user 0.020s	sys 0.029s Metrics: {"bytes_written":12717738,"delete_count":0,"lbm_write_time_us":22623,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:45.310727   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=2.188937
I20260812 06:17:45.322345 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.011s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4328,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:45.322872   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=2.188937
I20260812 06:17:45.333638 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3993,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:45.334530   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c): perf score=1.000000
I20260812 06:17:45.533226 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.198s	user 0.127s	sys 0.055s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774802,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":867,"lbm_read_time_us":11805,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30086,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:17:45.534029   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=14.095187
I20260812 06:17:45.584349 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.050s	user 0.035s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21967,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:45.584951   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=2.188937
I20260812 06:17:45.601089 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.016s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5827,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:45.601686   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c): perf score=1.000000
I20260812 06:17:45.757223 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.155s	user 0.112s	sys 0.031s 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":1088,"lbm_read_time_us":10610,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29136,"lbm_writes_lt_1ms":543,"mutex_wait_us":364,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:17:45.757951   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=14.095187
I20260812 06:17:45.806365 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.048s	user 0.029s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20638,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:45.806916   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=2.188937
I20260812 06:17:45.819154 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4335,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:45.819666   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushMRSOp(7b1290774aed4fd099345e6e68efc03c): perf score=1.000000
I20260812 06:17:45.852461 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushMRSOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.033s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":215,"dirs.run_wall_time_us":1363,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1760,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:45.853377   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling LogGCOp(7b1290774aed4fd099345e6e68efc03c): free 124257506 bytes of WAL
I20260812 06:17:45.853664 32766 log_reader.cc:385] T 7b1290774aed4fd099345e6e68efc03c: removed 12 log segments from log reader
I20260812 06:17:45.853713 32766 log.cc:1079] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/7b1290774aed4fd099345e6e68efc03c/wal-000000028 (ops 134-138)
I20260812 06:17:45.853765 32766 log.cc:1079] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/7b1290774aed4fd099345e6e68efc03c/wal-000000029 (ops 139-143)
I20260812 06:17:45.853811 32766 log.cc:1079] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/7b1290774aed4fd099345e6e68efc03c/wal-000000030 (ops 144-148)
I20260812 06:17:45.853857 32766 log.cc:1079] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/7b1290774aed4fd099345e6e68efc03c/wal-000000031 (ops 149-152)
I20260812 06:17:45.853904 32766 log.cc:1079] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/7b1290774aed4fd099345e6e68efc03c/wal-000000032 (ops 153-157)
I20260812 06:17:45.853955 32766 log.cc:1079] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/7b1290774aed4fd099345e6e68efc03c/wal-000000033 (ops 158-162)
I20260812 06:17:45.853998 32766 log.cc:1079] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/7b1290774aed4fd099345e6e68efc03c/wal-000000034 (ops 163-167)
I20260812 06:17:45.854039 32766 log.cc:1079] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/7b1290774aed4fd099345e6e68efc03c/wal-000000035 (ops 168-172)
I20260812 06:17:45.854076 32766 log.cc:1079] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/7b1290774aed4fd099345e6e68efc03c/wal-000000036 (ops 173-177)
I20260812 06:17:45.854148 32766 log.cc:1079] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/7b1290774aed4fd099345e6e68efc03c/wal-000000037 (ops 178-182)
I20260812 06:17:45.854193 32766 log.cc:1079] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/7b1290774aed4fd099345e6e68efc03c/wal-000000038 (ops 183-187)
I20260812 06:17:45.854231 32766 log.cc:1079] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/7b1290774aed4fd099345e6e68efc03c/wal-000000039 (ops 188-192)
I20260812 06:17:45.882989 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: LogGCOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.029s	user 0.002s	sys 0.027s Metrics: {}
I20260812 06:17:45.883574   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling UndoDeltaBlockGCOp(7b1290774aed4fd099345e6e68efc03c): 482 bytes on disk
I20260812 06:17:45.884104 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: UndoDeltaBlockGCOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:17:45.884660   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=4.173312
I20260812 06:17:45.902458 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.018s	user 0.009s	sys 0.008s Metrics: {"bytes_written":5661584,"delete_count":0,"lbm_write_time_us":7298,"lbm_writes_lt_1ms":141,"reinsert_count":0,"update_count":690}
I20260812 06:17:45.903056   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c): perf score=1.196750
I20260812 06:17:45.925660 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: FlushDeltaMemStoresOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.022s	user 0.011s	sys 0.007s Metrics: {"bytes_written":2543704,"delete_count":0,"lbm_write_time_us":4153,"lbm_writes_lt_1ms":65,"reinsert_count":0,"update_count":310}
I20260812 06:17:45.926309   369 maintenance_manager.cc:419] P c141d67065e348b9b80c7e3217836177: Scheduling MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c): perf score=1.000000
I20260812 06:17:46.019793 32641 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.021s	user 1.885s	sys 0.135s
I20260812 06:17:46.123116 32641 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.103s	user 0.003s	sys 0.000s
I20260812 06:17:46.123809 32641 tablet_server.cc:179] TabletServer@127.31.224.65:0 shutting down...
I20260812 06:17:46.141942 32766 maintenance_manager.cc:643] P c141d67065e348b9b80c7e3217836177: MajorDeltaCompactionOp(7b1290774aed4fd099345e6e68efc03c) complete. Timing: real 0.215s	user 0.149s	sys 0.065s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979715,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":961,"lbm_read_time_us":15251,"lbm_reads_lt_1ms":762,"lbm_write_time_us":33981,"lbm_writes_lt_1ms":743,"mutex_wait_us":372,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":18944,"thread_start_us":81,"threads_started":1,"update_count":3500}
I20260812 06:17:46.143487 32641 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:46.143872 32641 tablet_replica.cc:333] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177: stopping tablet replica
I20260812 06:17:46.144114 32641 raft_consensus.cc:2243] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:46.144361 32641 raft_consensus.cc:2272] T 7b1290774aed4fd099345e6e68efc03c P c141d67065e348b9b80c7e3217836177 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:46.161206 32641 tablet_server.cc:196] TabletServer@127.31.224.65:0 shutdown complete.
I20260812 06:17:46.202260 32641 master.cc:562] Master@127.31.224.126:34547 shutting down...
I20260812 06:17:46.205969 32641 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 50900254d6624d11914915540cdeea1c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:46.206207 32641 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 50900254d6624d11914915540cdeea1c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:46.206297 32641 tablet_replica.cc:333] T 00000000000000000000000000000000 P 50900254d6624d11914915540cdeea1c: stopping tablet replica
I20260812 06:17:46.218972 32641 master.cc:584] Master@127.31.224.126:34547 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5571 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:46.324435 32641 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.31.224.126:46607
I20260812 06:17:46.324996 32641 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:46.327163   406 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:46.327234   410 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:46.327307   407 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:46.327394 32641 server_base.cc:1061] running on GCE node
I20260812 06:17:46.327562 32641 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:46.327601 32641 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:46.327616 32641 hybrid_clock.cc:648] HybridClock initialized: now 1786515466327617 us; error 0 us; skew 500 ppm
I20260812 06:17:46.328469 32641 webserver.cc:533] Webserver started at http://127.31.224.126:44179/ using document root <none> and password file <none>
I20260812 06:17:46.328652 32641 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:46.328730 32641 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:46.328817 32641 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:46.329257 32641 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/master-0-root/instance:
uuid: "bfc42a76fe7d4e94bfd217e365c9852b"
format_stamp: "Formatted at 2026-08-12 06:17:46 on dist-test-slave-9jjr"
I20260812 06:17:46.330947 32641 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:46.331980   415 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:46.332312 32641 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:46.332403 32641 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/master-0-root
uuid: "bfc42a76fe7d4e94bfd217e365c9852b"
format_stamp: "Formatted at 2026-08-12 06:17:46 on dist-test-slave-9jjr"
I20260812 06:17:46.332491 32641 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-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:46.345698 32641 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:46.346357 32641 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:46.350927 32641 rpc_server.cc:307] RPC server started. Bound to: 127.31.224.126:46607
I20260812 06:17:46.352533   480 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.31.224.126:46607 every 8 connection(s)
I20260812 06:17:46.355809   481 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:46.358101   481 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P bfc42a76fe7d4e94bfd217e365c9852b: Bootstrap starting.
I20260812 06:17:46.359059   481 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P bfc42a76fe7d4e94bfd217e365c9852b: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:46.360235   481 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P bfc42a76fe7d4e94bfd217e365c9852b: No bootstrap required, opened a new log
I20260812 06:17:46.360673   481 raft_consensus.cc:359] T 00000000000000000000000000000000 P bfc42a76fe7d4e94bfd217e365c9852b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bfc42a76fe7d4e94bfd217e365c9852b" member_type: VOTER }
I20260812 06:17:46.360787   481 raft_consensus.cc:385] T 00000000000000000000000000000000 P bfc42a76fe7d4e94bfd217e365c9852b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:46.360847   481 raft_consensus.cc:740] T 00000000000000000000000000000000 P bfc42a76fe7d4e94bfd217e365c9852b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: bfc42a76fe7d4e94bfd217e365c9852b, State: Initialized, Role: FOLLOWER
I20260812 06:17:46.361027   481 consensus_queue.cc:260] T 00000000000000000000000000000000 P bfc42a76fe7d4e94bfd217e365c9852b [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: "bfc42a76fe7d4e94bfd217e365c9852b" member_type: VOTER }
I20260812 06:17:46.361126   481 raft_consensus.cc:399] T 00000000000000000000000000000000 P bfc42a76fe7d4e94bfd217e365c9852b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:46.361172   481 raft_consensus.cc:493] T 00000000000000000000000000000000 P bfc42a76fe7d4e94bfd217e365c9852b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:46.361227   481 raft_consensus.cc:3060] T 00000000000000000000000000000000 P bfc42a76fe7d4e94bfd217e365c9852b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:46.361966   481 raft_consensus.cc:515] T 00000000000000000000000000000000 P bfc42a76fe7d4e94bfd217e365c9852b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bfc42a76fe7d4e94bfd217e365c9852b" member_type: VOTER }
I20260812 06:17:46.362174   481 leader_election.cc:304] T 00000000000000000000000000000000 P bfc42a76fe7d4e94bfd217e365c9852b [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: bfc42a76fe7d4e94bfd217e365c9852b; no voters: 
I20260812 06:17:46.362408   481 leader_election.cc:290] T 00000000000000000000000000000000 P bfc42a76fe7d4e94bfd217e365c9852b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:46.362627   484 raft_consensus.cc:2804] T 00000000000000000000000000000000 P bfc42a76fe7d4e94bfd217e365c9852b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:46.362857   484 raft_consensus.cc:697] T 00000000000000000000000000000000 P bfc42a76fe7d4e94bfd217e365c9852b [term 1 LEADER]: Becoming Leader. State: Replica: bfc42a76fe7d4e94bfd217e365c9852b, State: Running, Role: LEADER
I20260812 06:17:46.362917   481 sys_catalog.cc:565] T 00000000000000000000000000000000 P bfc42a76fe7d4e94bfd217e365c9852b [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:46.363019   484 consensus_queue.cc:237] T 00000000000000000000000000000000 P bfc42a76fe7d4e94bfd217e365c9852b [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: "bfc42a76fe7d4e94bfd217e365c9852b" member_type: VOTER }
I20260812 06:17:46.363521   485 sys_catalog.cc:455] T 00000000000000000000000000000000 P bfc42a76fe7d4e94bfd217e365c9852b [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "bfc42a76fe7d4e94bfd217e365c9852b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bfc42a76fe7d4e94bfd217e365c9852b" member_type: VOTER } }
I20260812 06:17:46.363574   487 sys_catalog.cc:455] T 00000000000000000000000000000000 P bfc42a76fe7d4e94bfd217e365c9852b [sys.catalog]: SysCatalogTable state changed. Reason: New leader bfc42a76fe7d4e94bfd217e365c9852b. Latest consensus state: current_term: 1 leader_uuid: "bfc42a76fe7d4e94bfd217e365c9852b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bfc42a76fe7d4e94bfd217e365c9852b" member_type: VOTER } }
I20260812 06:17:46.363631   485 sys_catalog.cc:458] T 00000000000000000000000000000000 P bfc42a76fe7d4e94bfd217e365c9852b [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:46.363662   487 sys_catalog.cc:458] T 00000000000000000000000000000000 P bfc42a76fe7d4e94bfd217e365c9852b [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:46.363971   491 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:46.365046   491 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:46.365245 32641 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:46.366933   491 catalog_manager.cc:1383] Generated new cluster ID: ace353f4e2304efe828cb6ec6fe090a8
I20260812 06:17:46.366994   491 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:46.400136   491 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:46.400828   491 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:46.412042   491 catalog_manager.cc:6092] T 00000000000000000000000000000000 P bfc42a76fe7d4e94bfd217e365c9852b: Generated new TSK 0
I20260812 06:17:46.412310   491 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:46.430364 32641 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:46.432736   510 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:46.432740   506 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:46.432765   505 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:46.432840 32641 server_base.cc:1061] running on GCE node
I20260812 06:17:46.433329 32641 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:46.433393 32641 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:46.433419 32641 hybrid_clock.cc:648] HybridClock initialized: now 1786515466433419 us; error 0 us; skew 500 ppm
I20260812 06:17:46.434585 32641 webserver.cc:533] Webserver started at http://127.31.224.65:45603/ using document root <none> and password file <none>
I20260812 06:17:46.434787 32641 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:46.434849 32641 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:46.434929 32641 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:46.435434 32641 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root/instance:
uuid: "b0ee7a04e71f451285722cb138cc3d38"
format_stamp: "Formatted at 2026-08-12 06:17:46 on dist-test-slave-9jjr"
I20260812 06:17:46.437508 32641 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:17:46.445405   516 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:46.445793 32641 fs_manager.cc:730] Time spent opening block manager: real 0.007s	user 0.000s	sys 0.001s
I20260812 06:17:46.445911 32641 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root
uuid: "b0ee7a04e71f451285722cb138cc3d38"
format_stamp: "Formatted at 2026-08-12 06:17:46 on dist-test-slave-9jjr"
I20260812 06:17:46.446035 32641 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-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:46.457127 32641 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:46.457654 32641 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:46.458063 32641 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:46.458794 32641 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:46.458850 32641 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:46.458904 32641 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:46.458938 32641 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:46.465368 32641 rpc_server.cc:307] RPC server started. Bound to: 127.31.224.65:44431
I20260812 06:17:46.467389   590 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.31.224.65:44431 every 8 connection(s)
I20260812 06:17:46.478190   591 heartbeater.cc:344] Connected to a master server at 127.31.224.126:46607
I20260812 06:17:46.478361   591 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:46.478680   591 heartbeater.cc:507] Master 127.31.224.126:46607 requested a full tablet report, sending...
I20260812 06:17:46.479501   437 ts_manager.cc:194] Registered new tserver with Master: b0ee7a04e71f451285722cb138cc3d38 (127.31.224.65:44431)
I20260812 06:17:46.479998 32641 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013769882s
I20260812 06:17:46.480386   437 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:39128
I20260812 06:17:46.488469   437 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:39142:
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:46.499037   552 tablet_service.cc:1511] Processing CreateTablet for tablet f7e066aed2d9419896d1e7c8e2d69bfc (DEFAULT_TABLE table=heavy-update-compaction-test [id=9c3eb34beedb47c0aee825793c6ff53e]), partition=
I20260812 06:17:46.499400   552 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet f7e066aed2d9419896d1e7c8e2d69bfc. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:46.501489   609 tablet_bootstrap.cc:492] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Bootstrap starting.
I20260812 06:17:46.502969   609 tablet_bootstrap.cc:654] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:46.504436   609 tablet_bootstrap.cc:492] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: No bootstrap required, opened a new log
I20260812 06:17:46.504561   609 ts_tablet_manager.cc:1403] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Time spent bootstrapping tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:17:46.505231   609 raft_consensus.cc:359] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b0ee7a04e71f451285722cb138cc3d38" member_type: VOTER last_known_addr { host: "127.31.224.65" port: 44431 } }
I20260812 06:17:46.505425   609 raft_consensus.cc:385] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:46.505487   609 raft_consensus.cc:740] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b0ee7a04e71f451285722cb138cc3d38, State: Initialized, Role: FOLLOWER
I20260812 06:17:46.505662   609 consensus_queue.cc:260] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38 [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: "b0ee7a04e71f451285722cb138cc3d38" member_type: VOTER last_known_addr { host: "127.31.224.65" port: 44431 } }
I20260812 06:17:46.505776   609 raft_consensus.cc:399] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:46.505820   609 raft_consensus.cc:493] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:46.505872   609 raft_consensus.cc:3060] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:46.507138   609 raft_consensus.cc:515] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b0ee7a04e71f451285722cb138cc3d38" member_type: VOTER last_known_addr { host: "127.31.224.65" port: 44431 } }
I20260812 06:17:46.507326   609 leader_election.cc:304] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38 [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: b0ee7a04e71f451285722cb138cc3d38; no voters: 
I20260812 06:17:46.507606   609 leader_election.cc:290] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:46.507766   611 raft_consensus.cc:2804] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:46.507978   609 ts_tablet_manager.cc:1434] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Time spent starting tablet: real 0.003s	user 0.002s	sys 0.001s
I20260812 06:17:46.508014   611 raft_consensus.cc:697] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38 [term 1 LEADER]: Becoming Leader. State: Replica: b0ee7a04e71f451285722cb138cc3d38, State: Running, Role: LEADER
I20260812 06:17:46.508065   591 heartbeater.cc:499] Master 127.31.224.126:46607 was elected leader, sending a full tablet report...
I20260812 06:17:46.508154   611 consensus_queue.cc:237] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38 [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: "b0ee7a04e71f451285722cb138cc3d38" member_type: VOTER last_known_addr { host: "127.31.224.65" port: 44431 } }
I20260812 06:17:46.509455   437 catalog_manager.cc:5719] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38 reported cstate change: term changed from 0 to 1, leader changed from <none> to b0ee7a04e71f451285722cb138cc3d38 (127.31.224.65). New cstate: current_term: 1 leader_uuid: "b0ee7a04e71f451285722cb138cc3d38" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b0ee7a04e71f451285722cb138cc3d38" member_type: VOTER last_known_addr { host: "127.31.224.65" port: 44431 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:46.570297 32641 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.019s	sys 0.004s
I20260812 06:17:46.718037   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushMRSOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=19.054940
I20260812 06:17:46.888132   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushMRSOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.170s	user 0.120s	sys 0.039s Metrics: {"bytes_written":12307492,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":46,"dirs.run_cpu_time_us":196,"dirs.run_wall_time_us":782,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43128,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:17:46.888892   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling LogGCOp(f7e066aed2d9419896d1e7c8e2d69bfc): free 20743831 bytes of WAL
I20260812 06:17:46.889142   524 log_reader.cc:385] T f7e066aed2d9419896d1e7c8e2d69bfc: removed 2 log segments from log reader
I20260812 06:17:46.889187   524 log.cc:1079] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/f7e066aed2d9419896d1e7c8e2d69bfc/wal-000000001 (ops 1-6)
I20260812 06:17:46.889218   524 log.cc:1079] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/f7e066aed2d9419896d1e7c8e2d69bfc/wal-000000002 (ops 7-11)
I20260812 06:17:46.893455   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: LogGCOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:46.893935   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling UndoDeltaBlockGCOp(f7e066aed2d9419896d1e7c8e2d69bfc): 16411396 bytes on disk
I20260812 06:17:46.894464   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: UndoDeltaBlockGCOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:17:46.894899   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=2.188937
I20260812 06:17:46.907691   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4487,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:46.908282   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling MajorDeltaCompactionOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=1.000000
I20260812 06:17:47.063788   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: MajorDeltaCompactionOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.155s	user 0.124s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":338,"lbm_read_time_us":13469,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25942,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13184,"thread_start_us":378,"threads_started":5,"update_count":2000}
I20260812 06:17:47.064414   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=10.126437
I20260812 06:17:47.121264   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.057s	user 0.022s	sys 0.031s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21870,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":1500}
I20260812 06:17:47.121794   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=2.188937
I20260812 06:17:47.151628   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.030s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5023,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.152181   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=2.188937
I20260812 06:17:47.167800   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.015s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5867,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.168604   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling MajorDeltaCompactionOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=1.000000
I20260812 06:17:47.346659   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: MajorDeltaCompactionOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.178s	user 0.109s	sys 0.064s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774808,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":598,"lbm_read_time_us":12887,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30340,"lbm_writes_lt_1ms":543,"mutex_wait_us":393,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:17:47.347669   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=11.118625
I20260812 06:17:47.393047   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.045s	user 0.014s	sys 0.028s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":19571,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:47.393726   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=3.181125
I20260812 06:17:47.411655   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.018s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4553929,"delete_count":0,"lbm_write_time_us":6537,"lbm_writes_lt_1ms":114,"reinsert_count":0,"update_count":555}
I20260812 06:17:47.412192   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=2.188937
I20260812 06:17:47.421388   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3241130,"delete_count":0,"lbm_write_time_us":3245,"lbm_writes_lt_1ms":82,"reinsert_count":0,"update_count":395}
I20260812 06:17:47.421844   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling MajorDeltaCompactionOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=1.000000
I20260812 06:17:47.614283   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: MajorDeltaCompactionOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.192s	user 0.145s	sys 0.039s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774796,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":689,"lbm_read_time_us":13657,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32598,"lbm_writes_lt_1ms":543,"mutex_wait_us":74,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":30720,"update_count":2500}
I20260812 06:17:47.614940   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=14.095187
I20260812 06:17:47.671871   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.057s	user 0.032s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22300,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:47.672384   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=2.188937
I20260812 06:17:47.697546   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.025s	user 0.006s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5653,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.698343   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling MajorDeltaCompactionOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=1.000000
I20260812 06:17:47.892510   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: MajorDeltaCompactionOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.194s	user 0.128s	sys 0.064s 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":695,"lbm_read_time_us":13733,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32373,"lbm_writes_lt_1ms":543,"mutex_wait_us":311,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5120,"update_count":2500}
I20260812 06:17:47.893237   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=14.095187
I20260812 06:17:47.950781   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.057s	user 0.039s	sys 0.008s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":21063,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:47.951340   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=2.188937
I20260812 06:17:47.964123   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4367,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.965968   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling MajorDeltaCompactionOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=1.000000
I20260812 06:17:48.159472   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: MajorDeltaCompactionOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.193s	user 0.123s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":396,"lbm_read_time_us":12224,"lbm_reads_lt_1ms":568,"lbm_write_time_us":31338,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16896,"update_count":2500}
I20260812 06:17:48.160382   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=14.095187
I20260812 06:17:48.216960   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.056s	user 0.030s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22175,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:48.217496   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=2.188937
I20260812 06:17:48.230446   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4258,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:48.231106   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushMRSOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=1.000000
I20260812 06:17:48.264570   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushMRSOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.033s	user 0.028s	sys 0.003s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":90,"dirs.run_cpu_time_us":328,"dirs.run_wall_time_us":1403,"drs_written":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1689,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:48.265302   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling LogGCOp(f7e066aed2d9419896d1e7c8e2d69bfc): free 115943231 bytes of WAL
I20260812 06:17:48.265544   524 log_reader.cc:385] T f7e066aed2d9419896d1e7c8e2d69bfc: removed 11 log segments from log reader
I20260812 06:17:48.265606   524 log.cc:1079] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/f7e066aed2d9419896d1e7c8e2d69bfc/wal-000000003 (ops 12-16)
I20260812 06:17:48.265661   524 log.cc:1079] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/f7e066aed2d9419896d1e7c8e2d69bfc/wal-000000004 (ops 17-21)
I20260812 06:17:48.265719   524 log.cc:1079] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/f7e066aed2d9419896d1e7c8e2d69bfc/wal-000000005 (ops 22-26)
I20260812 06:17:48.265748   524 log.cc:1079] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/f7e066aed2d9419896d1e7c8e2d69bfc/wal-000000006 (ops 27-31)
I20260812 06:17:48.265789   524 log.cc:1079] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/f7e066aed2d9419896d1e7c8e2d69bfc/wal-000000007 (ops 32-36)
I20260812 06:17:48.265827   524 log.cc:1079] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/f7e066aed2d9419896d1e7c8e2d69bfc/wal-000000008 (ops 37-41)
I20260812 06:17:48.265864   524 log.cc:1079] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/f7e066aed2d9419896d1e7c8e2d69bfc/wal-000000009 (ops 42-46)
I20260812 06:17:48.265902   524 log.cc:1079] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/f7e066aed2d9419896d1e7c8e2d69bfc/wal-000000010 (ops 47-51)
I20260812 06:17:48.265940   524 log.cc:1079] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/f7e066aed2d9419896d1e7c8e2d69bfc/wal-000000011 (ops 52-56)
I20260812 06:17:48.265976   524 log.cc:1079] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/f7e066aed2d9419896d1e7c8e2d69bfc/wal-000000012 (ops 57-61)
I20260812 06:17:48.266013   524 log.cc:1079] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/f7e066aed2d9419896d1e7c8e2d69bfc/wal-000000013 (ops 62-66)
I20260812 06:17:48.292829   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: LogGCOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.027s	user 0.002s	sys 0.023s Metrics: {}
I20260812 06:17:48.293356   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling UndoDeltaBlockGCOp(f7e066aed2d9419896d1e7c8e2d69bfc): 462 bytes on disk
I20260812 06:17:48.293919   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: UndoDeltaBlockGCOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4}
I20260812 06:17:48.294494   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=3.181125
I20260812 06:17:48.318934   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.024s	user 0.014s	sys 0.005s Metrics: {"bytes_written":4841097,"delete_count":0,"lbm_write_time_us":7648,"lbm_writes_lt_1ms":121,"reinsert_count":0,"update_count":590}
I20260812 06:17:48.319602   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=2.188937
I20260812 06:17:48.329603   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3364205,"delete_count":0,"lbm_write_time_us":3478,"lbm_writes_lt_1ms":85,"reinsert_count":0,"update_count":410}
I20260812 06:17:48.330370   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling MajorDeltaCompactionOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=1.000000
I20260812 06:17:48.641700   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: MajorDeltaCompactionOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.311s	user 0.217s	sys 0.090s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979734,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1541,"lbm_read_time_us":17717,"lbm_reads_lt_1ms":774,"lbm_write_time_us":54899,"lbm_writes_lt_1ms":743,"mutex_wait_us":147,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":18176,"thread_start_us":174,"threads_started":1,"update_count":3500}
I20260812 06:17:48.643203   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=15.087375
I20260812 06:17:48.750181   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.107s	user 0.082s	sys 0.019s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":48234,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:48.750942   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=2.188937
I20260812 06:17:48.800840   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.050s	user 0.006s	sys 0.012s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":8139,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:48.801980   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=2.188937
I20260812 06:17:48.823331   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.021s	user 0.015s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7727,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:48.824674   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling MajorDeltaCompactionOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=1.000000
I20260812 06:17:49.333819   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: MajorDeltaCompactionOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.509s	user 0.362s	sys 0.135s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877206,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":2483,"lbm_read_time_us":25951,"lbm_reads_lt_1ms":673,"lbm_write_time_us":106542,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":641,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1408,"thread_start_us":1003,"threads_started":6,"update_count":3000}
I20260812 06:17:49.335175   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=16.079562
I20260812 06:17:49.583204   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.248s	user 0.098s	sys 0.075s Metrics: {"bytes_written":17845751,"delete_count":0,"lbm_write_time_us":81896,"lbm_writes_1-10_ms":5,"lbm_writes_lt_1ms":433,"reinsert_count":0,"update_count":2175}
I20260812 06:17:49.584931   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=5.165500
I20260812 06:17:49.636637   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.051s	user 0.014s	sys 0.028s Metrics: {"bytes_written":6769239,"delete_count":0,"lbm_write_time_us":20015,"lbm_writes_lt_1ms":168,"reinsert_count":0,"update_count":825}
I20260812 06:17:49.638347   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling MajorDeltaCompactionOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=1.000000
I20260812 06:17:49.969707   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: MajorDeltaCompactionOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.331s	user 0.221s	sys 0.108s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877112,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":483,"lbm_read_time_us":45645,"lbm_reads_lt_1ms":668,"lbm_write_time_us":35451,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8064,"thread_start_us":390,"threads_started":6,"update_count":3000}
I20260812 06:17:49.970388   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=16.079562
I20260812 06:17:50.025910   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.055s	user 0.041s	sys 0.009s Metrics: {"bytes_written":17845751,"delete_count":0,"lbm_write_time_us":23806,"lbm_writes_lt_1ms":438,"reinsert_count":0,"update_count":2175}
I20260812 06:17:50.026584   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=1.196750
I20260812 06:17:50.037240   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.010s	user 0.006s	sys 0.001s Metrics: {"bytes_written":3077034,"delete_count":0,"lbm_write_time_us":3106,"lbm_writes_lt_1ms":78,"reinsert_count":0,"update_count":375}
I20260812 06:17:50.037743   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=2.188937
I20260812 06:17:50.048243   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3813,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:50.048789   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling MajorDeltaCompactionOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=1.000000
I20260812 06:17:50.273214   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: MajorDeltaCompactionOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.224s	user 0.143s	sys 0.078s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877190,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":84,"lbm_read_time_us":16137,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35933,"lbm_writes_lt_1ms":643,"mutex_wait_us":3,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:17:50.273850   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=14.095187
I20260812 06:17:50.319077   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.045s	user 0.041s	sys 0.003s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19979,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:50.319664   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=2.188937
I20260812 06:17:50.344202   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.024s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5535,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:50.344663   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=2.188937
I20260812 06:17:50.355719   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4122,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:50.356184   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling MajorDeltaCompactionOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=1.000000
I20260812 06:17:50.577675   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: MajorDeltaCompactionOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.221s	user 0.149s	sys 0.072s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877219,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":939,"lbm_read_time_us":16812,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35961,"lbm_writes_lt_1ms":643,"mutex_wait_us":663,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13312,"update_count":3000}
I20260812 06:17:50.578445   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=14.095187
I20260812 06:17:50.638882   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.060s	user 0.035s	sys 0.020s Metrics: {"bytes_written":16409907,"delete_count":0,"lbm_write_time_us":25253,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:50.639559   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=2.188937
I20260812 06:17:50.655676   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5817,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:50.656450   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushMRSOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=1.000000
I20260812 06:17:50.689528   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushMRSOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.033s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":200,"dirs.run_wall_time_us":1303,"drs_written":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2277,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:50.690421   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling LogGCOp(f7e066aed2d9419896d1e7c8e2d69bfc): free 133477450 bytes of WAL
I20260812 06:17:50.690709   524 log_reader.cc:385] T f7e066aed2d9419896d1e7c8e2d69bfc: removed 13 log segments from log reader
I20260812 06:17:50.690773   524 log.cc:1079] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/f7e066aed2d9419896d1e7c8e2d69bfc/wal-000000014 (ops 67-71)
I20260812 06:17:50.690814   524 log.cc:1079] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/f7e066aed2d9419896d1e7c8e2d69bfc/wal-000000015 (ops 72-76)
I20260812 06:17:50.690845   524 log.cc:1079] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/f7e066aed2d9419896d1e7c8e2d69bfc/wal-000000016 (ops 77-81)
I20260812 06:17:50.690869   524 log.cc:1079] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/f7e066aed2d9419896d1e7c8e2d69bfc/wal-000000017 (ops 82-86)
I20260812 06:17:50.690898   524 log.cc:1079] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/f7e066aed2d9419896d1e7c8e2d69bfc/wal-000000018 (ops 87-91)
I20260812 06:17:50.690928   524 log.cc:1079] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/f7e066aed2d9419896d1e7c8e2d69bfc/wal-000000019 (ops 92-96)
I20260812 06:17:50.690963   524 log.cc:1079] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/f7e066aed2d9419896d1e7c8e2d69bfc/wal-000000020 (ops 97-101)
I20260812 06:17:50.690989   524 log.cc:1079] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/f7e066aed2d9419896d1e7c8e2d69bfc/wal-000000021 (ops 102-106)
I20260812 06:17:50.691015   524 log.cc:1079] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/f7e066aed2d9419896d1e7c8e2d69bfc/wal-000000022 (ops 107-111)
I20260812 06:17:50.691045   524 log.cc:1079] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/f7e066aed2d9419896d1e7c8e2d69bfc/wal-000000023 (ops 112-116)
I20260812 06:17:50.691066   524 log.cc:1079] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/f7e066aed2d9419896d1e7c8e2d69bfc/wal-000000024 (ops 117-121)
I20260812 06:17:50.691108   524 log.cc:1079] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/f7e066aed2d9419896d1e7c8e2d69bfc/wal-000000025 (ops 122-126)
I20260812 06:17:50.691136   524 log.cc:1079] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/f7e066aed2d9419896d1e7c8e2d69bfc/wal-000000026 (ops 127-131)
I20260812 06:17:50.727015   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: LogGCOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.036s	user 0.000s	sys 0.036s Metrics: {}
I20260812 06:17:50.727566   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling UndoDeltaBlockGCOp(f7e066aed2d9419896d1e7c8e2d69bfc): 484 bytes on disk
I20260812 06:17:50.728300   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: UndoDeltaBlockGCOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":126,"lbm_reads_lt_1ms":4}
I20260812 06:17:50.728917   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=2.188937
I20260812 06:17:50.750543   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.021s	user 0.008s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4607,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:50.751045   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=2.188937
I20260812 06:17:50.761691   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3989,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:50.762240   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling MajorDeltaCompactionOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=1.000000
I20260812 06:17:50.996589   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: MajorDeltaCompactionOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.234s	user 0.173s	sys 0.061s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979756,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":839,"lbm_read_time_us":16542,"lbm_reads_lt_1ms":774,"lbm_write_time_us":42828,"lbm_writes_lt_1ms":743,"mutex_wait_us":27,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":57856,"thread_start_us":127,"threads_started":1,"update_count":3500}
I20260812 06:17:50.997241   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=18.063937
I20260812 06:17:51.061599   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.064s	user 0.045s	sys 0.016s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":28636,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:51.062278   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=2.188937
I20260812 06:17:51.089366   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.027s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5971,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:51.089938   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=2.188937
I20260812 06:17:51.105217   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5919,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:51.105803   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling MajorDeltaCompactionOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=1.000000
I20260812 06:17:51.295826   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: MajorDeltaCompactionOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.190s	user 0.150s	sys 0.040s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979634,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":877,"lbm_read_time_us":13864,"lbm_reads_lt_1ms":773,"lbm_write_time_us":41488,"lbm_writes_lt_1ms":743,"mutex_wait_us":22,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":5760,"update_count":3500}
I20260812 06:17:51.296625   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=14.095187
I20260812 06:17:51.357671   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.061s	user 0.026s	sys 0.032s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":27235,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:17:51.358268   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=2.188937
I20260812 06:17:51.376008   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.018s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4403,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":500}
I20260812 06:17:51.376492   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=2.188937
I20260812 06:17:51.387845   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4276,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:51.388384   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling MajorDeltaCompactionOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=1.000000
I20260812 06:17:51.563623   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: MajorDeltaCompactionOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.175s	user 0.145s	sys 0.029s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877219,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":972,"lbm_read_time_us":11298,"lbm_reads_lt_1ms":673,"lbm_write_time_us":37197,"lbm_writes_lt_1ms":643,"mutex_wait_us":313,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":22016,"update_count":3000}
I20260812 06:17:51.564291   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=14.095187
I20260812 06:17:51.623255   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.059s	user 0.021s	sys 0.035s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":27617,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:17:51.623838   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=2.188937
I20260812 06:17:51.640614   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.017s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6415,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:51.641180   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling MajorDeltaCompactionOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=1.000000
I20260812 06:17:51.809796   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: MajorDeltaCompactionOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.168s	user 0.118s	sys 0.049s 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":1017,"lbm_read_time_us":10162,"lbm_reads_lt_1ms":564,"lbm_write_time_us":33152,"lbm_writes_lt_1ms":543,"mutex_wait_us":66,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19456,"update_count":2500}
I20260812 06:17:51.810560   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=14.095187
I20260812 06:17:51.879840   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.069s	user 0.019s	sys 0.036s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25078,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:51.880813   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=2.188937
I20260812 06:17:51.895028   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.014s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5073,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:51.895784   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling MajorDeltaCompactionOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=1.000000
I20260812 06:17:52.079602   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: MajorDeltaCompactionOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.184s	user 0.113s	sys 0.071s 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":518,"lbm_read_time_us":12665,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32121,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2500}
I20260812 06:17:52.080420   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=14.095187
I20260812 06:17:52.140472   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.060s	user 0.025s	sys 0.032s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23252,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:52.141104   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=2.188937
I20260812 06:17:52.152223   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4287,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:52.152774   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushMRSOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=1.000000
I20260812 06:17:52.195922   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushMRSOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.043s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":254,"dirs.run_wall_time_us":1508,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2312,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:52.196817   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling LogGCOp(f7e066aed2d9419896d1e7c8e2d69bfc): free 124257506 bytes of WAL
I20260812 06:17:52.197095   524 log_reader.cc:385] T f7e066aed2d9419896d1e7c8e2d69bfc: removed 12 log segments from log reader
I20260812 06:17:52.197144   524 log.cc:1079] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/f7e066aed2d9419896d1e7c8e2d69bfc/wal-000000027 (ops 132-136)
I20260812 06:17:52.197211   524 log.cc:1079] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/f7e066aed2d9419896d1e7c8e2d69bfc/wal-000000028 (ops 137-141)
I20260812 06:17:52.197268   524 log.cc:1079] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/f7e066aed2d9419896d1e7c8e2d69bfc/wal-000000029 (ops 142-146)
I20260812 06:17:52.197328   524 log.cc:1079] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/f7e066aed2d9419896d1e7c8e2d69bfc/wal-000000030 (ops 147-151)
I20260812 06:17:52.197372   524 log.cc:1079] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/f7e066aed2d9419896d1e7c8e2d69bfc/wal-000000031 (ops 152-156)
I20260812 06:17:52.197431   524 log.cc:1079] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/f7e066aed2d9419896d1e7c8e2d69bfc/wal-000000032 (ops 157-160)
I20260812 06:17:52.197476   524 log.cc:1079] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/f7e066aed2d9419896d1e7c8e2d69bfc/wal-000000033 (ops 161-165)
I20260812 06:17:52.197520   524 log.cc:1079] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/f7e066aed2d9419896d1e7c8e2d69bfc/wal-000000034 (ops 166-170)
I20260812 06:17:52.197567   524 log.cc:1079] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/f7e066aed2d9419896d1e7c8e2d69bfc/wal-000000035 (ops 171-175)
I20260812 06:17:52.197611   524 log.cc:1079] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/f7e066aed2d9419896d1e7c8e2d69bfc/wal-000000036 (ops 176-180)
I20260812 06:17:52.197654   524 log.cc:1079] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/f7e066aed2d9419896d1e7c8e2d69bfc/wal-000000037 (ops 181-185)
I20260812 06:17:52.197696   524 log.cc:1079] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: Deleting log segment in path: /tmp/dist-test-tasknVWh3H/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460727644-32641-0/minicluster-data/ts-0-root/wals/f7e066aed2d9419896d1e7c8e2d69bfc/wal-000000038 (ops 186-190)
I20260812 06:17:52.228304   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: LogGCOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.031s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:17:52.228820   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling UndoDeltaBlockGCOp(f7e066aed2d9419896d1e7c8e2d69bfc): 472 bytes on disk
I20260812 06:17:52.229640   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: UndoDeltaBlockGCOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4}
I20260812 06:17:52.230355   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=4.173312
I20260812 06:17:52.249287   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.019s	user 0.008s	sys 0.008s Metrics: {"bytes_written":5743633,"delete_count":0,"lbm_write_time_us":8048,"lbm_writes_lt_1ms":143,"reinsert_count":0,"update_count":700}
I20260812 06:17:52.249861   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=1.196750
I20260812 06:17:52.258087   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.008s	user 0.003s	sys 0.003s Metrics: {"bytes_written":2461654,"delete_count":0,"lbm_write_time_us":2710,"lbm_writes_lt_1ms":63,"reinsert_count":0,"update_count":300}
I20260812 06:17:52.259234   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling MajorDeltaCompactionOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=1.000000
I20260812 06:17:52.440718 32641 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.870s	user 2.153s	sys 0.161s
I20260812 06:17:52.486757   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: MajorDeltaCompactionOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.227s	user 0.171s	sys 0.056s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979712,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":16550,"lbm_reads_lt_1ms":770,"lbm_write_time_us":42268,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":3500}
I20260812 06:17:52.487247   592 maintenance_manager.cc:419] P b0ee7a04e71f451285722cb138cc3d38: Scheduling FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc): perf score=14.095187
I20260812 06:17:52.517761 32641 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.077s	user 0.000s	sys 0.000s
I20260812 06:17:52.518440 32641 tablet_server.cc:179] TabletServer@127.31.224.65:0 shutting down...
I20260812 06:17:52.531813   524 maintenance_manager.cc:643] P b0ee7a04e71f451285722cb138cc3d38: FlushDeltaMemStoresOp(f7e066aed2d9419896d1e7c8e2d69bfc) complete. Timing: real 0.044s	user 0.027s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19464,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:52.532502 32641 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:52.532742 32641 tablet_replica.cc:333] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38: stopping tablet replica
I20260812 06:17:52.532928 32641 raft_consensus.cc:2243] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:52.533124 32641 raft_consensus.cc:2272] T f7e066aed2d9419896d1e7c8e2d69bfc P b0ee7a04e71f451285722cb138cc3d38 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:52.536881 32641 tablet_server.cc:196] TabletServer@127.31.224.65:0 shutdown complete.
I20260812 06:17:52.558705 32641 master.cc:562] Master@127.31.224.126:46607 shutting down...
I20260812 06:17:52.562469 32641 raft_consensus.cc:2243] T 00000000000000000000000000000000 P bfc42a76fe7d4e94bfd217e365c9852b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:52.562693 32641 raft_consensus.cc:2272] T 00000000000000000000000000000000 P bfc42a76fe7d4e94bfd217e365c9852b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:52.562803 32641 tablet_replica.cc:333] T 00000000000000000000000000000000 P bfc42a76fe7d4e94bfd217e365c9852b: stopping tablet replica
I20260812 06:17:52.575453 32641 master.cc:584] Master@127.31.224.126:46607 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (6357 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11930 ms total)

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