[==========] 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:19:16.338418  7641 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.7.118.126:38317
I20260812 06:19:16.339409  7641 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:19:16.340025  7641 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:16.346419  7647 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:19:16.346557  7641 server_base.cc:1061] running on GCE node
W20260812 06:19:16.346436  7650 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:19:16.346768  7648 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:19:16.347288  7641 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:16.347405  7641 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:19:16.347455  7641 hybrid_clock.cc:648] HybridClock initialized: now 1786515556347452 us; error 0 us; skew 500 ppm
I20260812 06:19:16.349293  7641 webserver.cc:533] Webserver started at http://127.7.118.126:39353/ using document root <none> and password file <none>
I20260812 06:19:16.349849  7641 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:16.349906  7641 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:16.350190  7641 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:16.351797  7641 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/master-0-root/instance:
uuid: "290a327640ce4ea2bd337ecff20cb15d"
format_stamp: "Formatted at 2026-08-12 06:19:16 on dist-test-slave-1jjb"
I20260812 06:19:16.355290  7641 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.001s	sys 0.002s
I20260812 06:19:16.357385  7655 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:19:16.358361  7641 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:16.358498  7641 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/master-0-root
uuid: "290a327640ce4ea2bd337ecff20cb15d"
format_stamp: "Formatted at 2026-08-12 06:19:16 on dist-test-slave-1jjb"
I20260812 06:19:16.358623  7641 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-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:19:16.383711  7641 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:16.384460  7641 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:19:16.384651  7641 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:16.392060  7641 rpc_server.cc:307] RPC server started. Bound to: 127.7.118.126:38317
I20260812 06:19:16.392103  7712 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.7.118.126:38317 every 8 connection(s)
I20260812 06:19:16.394371  7713 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:19:16.399766  7713 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 290a327640ce4ea2bd337ecff20cb15d: Bootstrap starting.
I20260812 06:19:16.402096  7713 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 290a327640ce4ea2bd337ecff20cb15d: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:16.402930  7713 log.cc:826] T 00000000000000000000000000000000 P 290a327640ce4ea2bd337ecff20cb15d: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:16.404605  7713 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 290a327640ce4ea2bd337ecff20cb15d: No bootstrap required, opened a new log
I20260812 06:19:16.407310  7713 raft_consensus.cc:359] T 00000000000000000000000000000000 P 290a327640ce4ea2bd337ecff20cb15d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "290a327640ce4ea2bd337ecff20cb15d" member_type: VOTER }
I20260812 06:19:16.407476  7713 raft_consensus.cc:385] T 00000000000000000000000000000000 P 290a327640ce4ea2bd337ecff20cb15d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:16.407526  7713 raft_consensus.cc:740] T 00000000000000000000000000000000 P 290a327640ce4ea2bd337ecff20cb15d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 290a327640ce4ea2bd337ecff20cb15d, State: Initialized, Role: FOLLOWER
I20260812 06:19:16.408185  7713 consensus_queue.cc:260] T 00000000000000000000000000000000 P 290a327640ce4ea2bd337ecff20cb15d [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: "290a327640ce4ea2bd337ecff20cb15d" member_type: VOTER }
I20260812 06:19:16.408331  7713 raft_consensus.cc:399] T 00000000000000000000000000000000 P 290a327640ce4ea2bd337ecff20cb15d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:16.408380  7713 raft_consensus.cc:493] T 00000000000000000000000000000000 P 290a327640ce4ea2bd337ecff20cb15d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:16.408470  7713 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 290a327640ce4ea2bd337ecff20cb15d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:16.409194  7713 raft_consensus.cc:515] T 00000000000000000000000000000000 P 290a327640ce4ea2bd337ecff20cb15d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "290a327640ce4ea2bd337ecff20cb15d" member_type: VOTER }
I20260812 06:19:16.409584  7713 leader_election.cc:304] T 00000000000000000000000000000000 P 290a327640ce4ea2bd337ecff20cb15d [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: 290a327640ce4ea2bd337ecff20cb15d; no voters: 
I20260812 06:19:16.409844  7713 leader_election.cc:290] T 00000000000000000000000000000000 P 290a327640ce4ea2bd337ecff20cb15d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:16.409991  7717 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 290a327640ce4ea2bd337ecff20cb15d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:16.410264  7717 raft_consensus.cc:697] T 00000000000000000000000000000000 P 290a327640ce4ea2bd337ecff20cb15d [term 1 LEADER]: Becoming Leader. State: Replica: 290a327640ce4ea2bd337ecff20cb15d, State: Running, Role: LEADER
I20260812 06:19:16.410668  7717 consensus_queue.cc:237] T 00000000000000000000000000000000 P 290a327640ce4ea2bd337ecff20cb15d [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: "290a327640ce4ea2bd337ecff20cb15d" member_type: VOTER }
I20260812 06:19:16.410863  7713 sys_catalog.cc:565] T 00000000000000000000000000000000 P 290a327640ce4ea2bd337ecff20cb15d [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:16.412689  7718 sys_catalog.cc:455] T 00000000000000000000000000000000 P 290a327640ce4ea2bd337ecff20cb15d [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "290a327640ce4ea2bd337ecff20cb15d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "290a327640ce4ea2bd337ecff20cb15d" member_type: VOTER } }
I20260812 06:19:16.412727  7719 sys_catalog.cc:455] T 00000000000000000000000000000000 P 290a327640ce4ea2bd337ecff20cb15d [sys.catalog]: SysCatalogTable state changed. Reason: New leader 290a327640ce4ea2bd337ecff20cb15d. Latest consensus state: current_term: 1 leader_uuid: "290a327640ce4ea2bd337ecff20cb15d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "290a327640ce4ea2bd337ecff20cb15d" member_type: VOTER } }
I20260812 06:19:16.412798  7718 sys_catalog.cc:458] T 00000000000000000000000000000000 P 290a327640ce4ea2bd337ecff20cb15d [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:16.412827  7719 sys_catalog.cc:458] T 00000000000000000000000000000000 P 290a327640ce4ea2bd337ecff20cb15d [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:16.413594  7641 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:19:16.415542  7733 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 290a327640ce4ea2bd337ecff20cb15d: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:19:16.415606  7733 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:19:16.415696  7728 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:16.416566  7728 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:16.421646  7728 catalog_manager.cc:1383] Generated new cluster ID: fc8227d1bf2444d2ac133cfc053c3649
I20260812 06:19:16.421777  7728 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:16.432968  7728 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:16.433907  7728 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:16.445318  7728 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 290a327640ce4ea2bd337ecff20cb15d: Generated new TSK 0
I20260812 06:19:16.446038  7728 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:16.478597  7641 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:16.481632  7737 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:19:16.481724  7641 server_base.cc:1061] running on GCE node
W20260812 06:19:16.481673  7738 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:19:16.481882  7740 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:16.482111  7641 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:16.482177  7641 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:19:16.482218  7641 hybrid_clock.cc:648] HybridClock initialized: now 1786515556482217 us; error 0 us; skew 500 ppm
I20260812 06:19:16.483198  7641 webserver.cc:533] Webserver started at http://127.7.118.65:39833/ using document root <none> and password file <none>
I20260812 06:19:16.483385  7641 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:16.483461  7641 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:16.483541  7641 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:16.484004  7641 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/instance:
uuid: "805118e162074090b034168342871582"
format_stamp: "Formatted at 2026-08-12 06:19:16 on dist-test-slave-1jjb"
I20260812 06:19:16.485596  7641 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:16.486629  7745 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:19:16.486882  7641 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:16.486963  7641 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root
uuid: "805118e162074090b034168342871582"
format_stamp: "Formatted at 2026-08-12 06:19:16 on dist-test-slave-1jjb"
I20260812 06:19:16.487058  7641 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-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:19:16.498672  7641 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:16.499178  7641 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:16.499739  7641 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:16.500685  7641 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:16.500738  7641 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:16.500813  7641 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:16.500854  7641 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:16.507858  7641 rpc_server.cc:307] RPC server started. Bound to: 127.7.118.65:43983
I20260812 06:19:16.507884  7813 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.7.118.65:43983 every 8 connection(s)
I20260812 06:19:16.518253  7814 heartbeater.cc:344] Connected to a master server at 127.7.118.126:38317
I20260812 06:19:16.518536  7814 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:16.519008  7814 heartbeater.cc:507] Master 127.7.118.126:38317 requested a full tablet report, sending...
I20260812 06:19:16.520524  7675 ts_manager.cc:194] Registered new tserver with Master: 805118e162074090b034168342871582 (127.7.118.65:43983)
I20260812 06:19:16.520996  7641 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012376742s
I20260812 06:19:16.521731  7675 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:41474
I20260812 06:19:16.531626  7675 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:41480:
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:19:16.547160  7775 tablet_service.cc:1511] Processing CreateTablet for tablet 7a0e327e6ae348eaa19c52fe8b89b9b8 (DEFAULT_TABLE table=heavy-update-compaction-test [id=f7c7ba0842734ca08480b60e12d879c8]), partition=
I20260812 06:19:16.547721  7775 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 7a0e327e6ae348eaa19c52fe8b89b9b8. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:16.550904  7827 tablet_bootstrap.cc:492] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Bootstrap starting.
I20260812 06:19:16.552256  7827 tablet_bootstrap.cc:654] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:16.553644  7827 tablet_bootstrap.cc:492] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: No bootstrap required, opened a new log
I20260812 06:19:16.553862  7827 ts_tablet_manager.cc:1403] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Time spent bootstrapping tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:19:16.554401  7827 raft_consensus.cc:359] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "805118e162074090b034168342871582" member_type: VOTER last_known_addr { host: "127.7.118.65" port: 43983 } }
I20260812 06:19:16.554510  7827 raft_consensus.cc:385] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:16.554536  7827 raft_consensus.cc:740] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 805118e162074090b034168342871582, State: Initialized, Role: FOLLOWER
I20260812 06:19:16.554709  7827 consensus_queue.cc:260] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582 [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: "805118e162074090b034168342871582" member_type: VOTER last_known_addr { host: "127.7.118.65" port: 43983 } }
I20260812 06:19:16.554791  7827 raft_consensus.cc:399] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:16.554849  7827 raft_consensus.cc:493] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:16.554929  7827 raft_consensus.cc:3060] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:16.556142  7827 raft_consensus.cc:515] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "805118e162074090b034168342871582" member_type: VOTER last_known_addr { host: "127.7.118.65" port: 43983 } }
I20260812 06:19:16.556320  7827 leader_election.cc:304] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582 [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: 805118e162074090b034168342871582; no voters: 
I20260812 06:19:16.556608  7827 leader_election.cc:290] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:16.556728  7829 raft_consensus.cc:2804] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:16.556995  7829 raft_consensus.cc:697] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582 [term 1 LEADER]: Becoming Leader. State: Replica: 805118e162074090b034168342871582, State: Running, Role: LEADER
I20260812 06:19:16.557044  7827 ts_tablet_manager.cc:1434] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Time spent starting tablet: real 0.003s	user 0.002s	sys 0.002s
I20260812 06:19:16.557224  7829 consensus_queue.cc:237] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582 [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: "805118e162074090b034168342871582" member_type: VOTER last_known_addr { host: "127.7.118.65" port: 43983 } }
I20260812 06:19:16.557411  7814 heartbeater.cc:499] Master 127.7.118.126:38317 was elected leader, sending a full tablet report...
I20260812 06:19:16.560140  7675 catalog_manager.cc:5719] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582 reported cstate change: term changed from 0 to 1, leader changed from <none> to 805118e162074090b034168342871582 (127.7.118.65). New cstate: current_term: 1 leader_uuid: "805118e162074090b034168342871582" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "805118e162074090b034168342871582" member_type: VOTER last_known_addr { host: "127.7.118.65" port: 43983 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:16.630541  7641 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.061s	user 0.020s	sys 0.009s
I20260812 06:19:16.759119  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushMRSOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=15.086190
I20260812 06:19:16.918277  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushMRSOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.159s	user 0.127s	sys 0.028s Metrics: {"bytes_written":11897249,"cfile_init":1,"compiler_manager_pool.queue_time_us":313,"delete_count":0,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":227,"dirs.run_wall_time_us":759,"drs_written":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40273,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":157,"threads_started":1,"update_count":1450}
I20260812 06:19:16.919446  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling LogGCOp(7a0e327e6ae348eaa19c52fe8b89b9b8): free 20743880 bytes of WAL
I20260812 06:19:16.919764  7750 log_reader.cc:385] T 7a0e327e6ae348eaa19c52fe8b89b9b8: removed 2 log segments from log reader
I20260812 06:19:16.919836  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000001 (ops 1-6)
I20260812 06:19:16.919901  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000002 (ops 7-11)
I20260812 06:19:16.925772  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: LogGCOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.006s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:19:16.926167  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=2.188937
I20260812 06:19:16.941696  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.015s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5786,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:16.942350  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling UndoDeltaBlockGCOp(7a0e327e6ae348eaa19c52fe8b89b9b8): 12719216 bytes on disk
I20260812 06:19:16.943105  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: UndoDeltaBlockGCOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:19:16.943552  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=1.000000
I20260812 06:19:17.070218  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.127s	user 0.095s	sys 0.032s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262036,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":58,"lbm_read_time_us":8922,"lbm_reads_lt_1ms":450,"lbm_write_time_us":25011,"lbm_writes_lt_1ms":433,"peak_mem_usage":49238594,"reinsert_count":0,"thread_start_us":214,"threads_started":5,"update_count":1950}
I20260812 06:19:17.070713  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=10.126437
I20260812 06:19:17.112697  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.042s	user 0.031s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16852,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:17.113274  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=2.188937
I20260812 06:19:17.124735  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4073,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:17.125335  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=1.000000
I20260812 06:19:17.253278  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.128s	user 0.102s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":236,"lbm_read_time_us":8581,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25732,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:17.254002  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=10.126437
I20260812 06:19:17.298015  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.044s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18078,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:17.298522  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=2.188937
I20260812 06:19:17.309706  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3994,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:17.310312  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=1.000000
I20260812 06:19:17.436066  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.126s	user 0.101s	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":634,"lbm_read_time_us":9949,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24809,"lbm_writes_lt_1ms":443,"mutex_wait_us":3,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:19:17.436916  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=10.126437
I20260812 06:19:17.492413  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.055s	user 0.019s	sys 0.034s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19327,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:17.493211  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=2.188937
I20260812 06:19:17.511901  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.018s	user 0.004s	sys 0.012s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6993,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:17.512459  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=1.000000
I20260812 06:19:17.658578  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.145s	user 0.107s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":236,"lbm_read_time_us":10490,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25244,"lbm_writes_lt_1ms":443,"mutex_wait_us":35,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12160,"update_count":2000}
I20260812 06:19:17.659266  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=10.126437
I20260812 06:19:17.697126  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.038s	user 0.021s	sys 0.015s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":15474,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:17.697615  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=2.188937
I20260812 06:19:17.711097  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5046,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:17.711623  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=1.000000
I20260812 06:19:17.844696  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.133s	user 0.105s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672280,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":290,"lbm_read_time_us":9489,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26760,"lbm_writes_lt_1ms":443,"mutex_wait_us":95,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:19:17.845419  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=10.126437
I20260812 06:19:17.886340  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.041s	user 0.030s	sys 0.004s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15895,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:17.886888  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=2.188937
I20260812 06:19:17.898955  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4364,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:17.899626  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=1.000000
I20260812 06:19:18.027897  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.128s	user 0.108s	sys 0.020s 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":238,"lbm_read_time_us":9797,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24744,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":2000}
I20260812 06:19:18.028486  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=10.126437
I20260812 06:19:18.078727  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.050s	user 0.025s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16445,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:18.079293  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=2.188937
I20260812 06:19:18.090257  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4184,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:18.090740  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=1.000000
I20260812 06:19:18.244251  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.153s	user 0.095s	sys 0.054s 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":2456,"lbm_read_time_us":11720,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25672,"lbm_writes_lt_1ms":443,"mutex_wait_us":1501,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":2000}
I20260812 06:19:18.245055  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=10.126437
I20260812 06:19:18.281160  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.036s	user 0.017s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14808,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:18.281716  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushMRSOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=1.000000
I20260812 06:19:18.318800  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushMRSOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.037s	user 0.023s	sys 0.003s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":248,"dirs.run_wall_time_us":1228,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1845,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:18.319793  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling UndoDeltaBlockGCOp(7a0e327e6ae348eaa19c52fe8b89b9b8): 482 bytes on disk
I20260812 06:19:18.320452  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: UndoDeltaBlockGCOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:19:18.321044  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=3.181125
I20260812 06:19:18.333029  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4563,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:18.333490  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling LogGCOp(7a0e327e6ae348eaa19c52fe8b89b9b8): free 125163585 bytes of WAL
I20260812 06:19:18.333775  7750 log_reader.cc:385] T 7a0e327e6ae348eaa19c52fe8b89b9b8: removed 13 log segments from log reader
I20260812 06:19:18.333840  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000003 (ops 12-16)
I20260812 06:19:18.333879  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000004 (ops 17-20)
I20260812 06:19:18.333904  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000005 (ops 21-25)
I20260812 06:19:18.333925  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000006 (ops 26-30)
I20260812 06:19:18.333968  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000007 (ops 31-34)
I20260812 06:19:18.333995  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000008 (ops 35-39)
I20260812 06:19:18.334017  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000009 (ops 40-44)
I20260812 06:19:18.334048  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000010 (ops 45-48)
I20260812 06:19:18.334076  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000011 (ops 49-53)
I20260812 06:19:18.334105  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000012 (ops 54-58)
I20260812 06:19:18.334141  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000013 (ops 59-62)
I20260812 06:19:18.334172  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000014 (ops 63-67)
I20260812 06:19:18.334201  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000015 (ops 68-72)
I20260812 06:19:18.367167  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: LogGCOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.033s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:19:18.367591  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=2.188937
I20260812 06:19:18.389369  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.022s	user 0.003s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4281,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:18.389775  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=2.188937
I20260812 06:19:18.408299  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.018s	user 0.007s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4096,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:18.408807  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=1.000000
I20260812 06:19:18.612632  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.204s	user 0.134s	sys 0.057s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877326,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":563,"lbm_read_time_us":16064,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33423,"lbm_writes_lt_1ms":643,"mutex_wait_us":24,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14208,"thread_start_us":77,"threads_started":1,"update_count":3000}
I20260812 06:19:18.613327  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=14.095187
I20260812 06:19:18.677018  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.064s	user 0.028s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18834,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:18.677556  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=2.188937
I20260812 06:19:18.693787  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.016s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6033,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:18.694355  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=1.000000
I20260812 06:19:18.871692  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.177s	user 0.113s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":655,"lbm_read_time_us":13001,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31197,"lbm_writes_lt_1ms":543,"mutex_wait_us":92,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11904,"update_count":2500}
I20260812 06:19:18.872440  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=10.126437
I20260812 06:19:18.914516  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.042s	user 0.035s	sys 0.001s Metrics: {"bytes_written":12307495,"delete_count":0,"lbm_write_time_us":16780,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:18.915022  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=2.188937
I20260812 06:19:18.930281  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5707,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:18.930848  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=1.000000
I20260812 06:19:19.067701  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.137s	user 0.108s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672282,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":722,"lbm_read_time_us":10856,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25185,"lbm_writes_lt_1ms":443,"mutex_wait_us":309,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10368,"update_count":2000}
I20260812 06:19:19.068416  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=10.126437
I20260812 06:19:19.116292  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.048s	user 0.016s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16537,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:19.116740  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=2.188937
I20260812 06:19:19.127748  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4156,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:19.128394  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=1.000000
I20260812 06:19:19.255322  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.127s	user 0.069s	sys 0.057s 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":702,"lbm_read_time_us":9590,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25635,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5760,"update_count":2000}
I20260812 06:19:19.255896  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=10.126437
I20260812 06:19:19.315419  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.059s	user 0.025s	sys 0.027s Metrics: {"bytes_written":12307487,"delete_count":0,"lbm_write_time_us":25848,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:19:19.315945  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=2.188937
I20260812 06:19:19.327514  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.011s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4187,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:19.328064  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=1.000000
I20260812 06:19:19.460062  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.132s	user 0.106s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":110,"lbm_read_time_us":9760,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25584,"lbm_writes_lt_1ms":443,"mutex_wait_us":29,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:19:19.460697  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=10.126437
I20260812 06:19:19.509698  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.049s	user 0.032s	sys 0.015s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18925,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:19.510282  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=2.188937
I20260812 06:19:19.522385  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4587,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:19.523077  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=1.000000
I20260812 06:19:19.688117  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.165s	user 0.106s	sys 0.057s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":975,"lbm_read_time_us":11582,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29029,"lbm_writes_lt_1ms":443,"mutex_wait_us":626,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:19.688719  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=10.126437
I20260812 06:19:19.723486  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.035s	user 0.025s	sys 0.007s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14956,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:19.723992  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=2.188937
I20260812 06:19:19.738271  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.014s	user 0.003s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5286,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:19.738740  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=1.000000
I20260812 06:19:19.881664  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.143s	user 0.106s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1351,"lbm_read_time_us":11056,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27510,"lbm_writes_lt_1ms":443,"mutex_wait_us":402,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2000}
I20260812 06:19:19.882292  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=11.118625
I20260812 06:19:19.920552  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.038s	user 0.016s	sys 0.021s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":16233,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:19.921245  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=2.188937
I20260812 06:19:19.934764  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5034,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:19.935397  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushMRSOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=1.000000
I20260812 06:19:19.993932  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushMRSOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.058s	user 0.041s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":102,"dirs.run_cpu_time_us":231,"dirs.run_wall_time_us":1327,"drs_written":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2185,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:19.994871  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling LogGCOp(7a0e327e6ae348eaa19c52fe8b89b9b8): free 128867472 bytes of WAL
I20260812 06:19:19.995128  7750 log_reader.cc:385] T 7a0e327e6ae348eaa19c52fe8b89b9b8: removed 13 log segments from log reader
I20260812 06:19:19.995200  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000016 (ops 73-76)
I20260812 06:19:19.995254  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000017 (ops 77-81)
I20260812 06:19:19.995311  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000018 (ops 82-86)
I20260812 06:19:19.995359  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000019 (ops 87-90)
I20260812 06:19:19.995396  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000020 (ops 91-95)
I20260812 06:19:19.995446  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000021 (ops 96-100)
I20260812 06:19:19.995481  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000022 (ops 101-104)
I20260812 06:19:19.995519  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000023 (ops 105-109)
I20260812 06:19:19.995555  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000024 (ops 110-114)
I20260812 06:19:19.995592  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000025 (ops 115-119)
I20260812 06:19:19.995630  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000026 (ops 120-124)
I20260812 06:19:19.995666  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000027 (ops 125-129)
I20260812 06:19:19.995702  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000028 (ops 130-134)
I20260812 06:19:20.026116  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: LogGCOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.031s	user 0.002s	sys 0.027s Metrics: {}
I20260812 06:19:20.026582  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling UndoDeltaBlockGCOp(7a0e327e6ae348eaa19c52fe8b89b9b8): 493 bytes on disk
I20260812 06:19:20.027114  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: UndoDeltaBlockGCOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:19:20.027743  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=7.149875
I20260812 06:19:20.053013  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.025s	user 0.017s	sys 0.007s Metrics: {"bytes_written":8779420,"delete_count":0,"lbm_write_time_us":10496,"lbm_writes_lt_1ms":217,"reinsert_count":0,"update_count":1070}
I20260812 06:19:20.053599  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=2.188937
I20260812 06:19:20.072335  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.019s	user 0.014s	sys 0.000s Metrics: {"bytes_written":3528305,"delete_count":0,"lbm_write_time_us":5581,"lbm_writes_lt_1ms":89,"reinsert_count":0,"update_count":430}
I20260812 06:19:20.072844  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=1.000000
I20260812 06:19:20.263851  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.191s	user 0.130s	sys 0.060s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979730,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":491,"lbm_read_time_us":14689,"lbm_reads_lt_1ms":766,"lbm_write_time_us":38654,"lbm_writes_lt_1ms":743,"mutex_wait_us":38,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":22656,"thread_start_us":80,"threads_started":1,"update_count":3500}
I20260812 06:19:20.264804  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=14.095187
I20260812 06:19:20.315622  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.051s	user 0.035s	sys 0.012s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":23020,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:20.316243  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=2.188937
I20260812 06:19:20.341521  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.025s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5968,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:20.342149  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=1.000000
I20260812 06:19:20.524556  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.182s	user 0.125s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":556,"lbm_read_time_us":12530,"lbm_reads_lt_1ms":564,"lbm_write_time_us":32204,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2500}
I20260812 06:19:20.525229  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=14.095187
I20260812 06:19:20.575106  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.050s	user 0.030s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20147,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:20.575609  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=2.188937
I20260812 06:19:20.587441  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4107,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:20.588531  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=1.000000
I20260812 06:19:20.762630  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.174s	user 0.133s	sys 0.031s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":877,"lbm_read_time_us":9536,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29336,"lbm_writes_lt_1ms":543,"mutex_wait_us":362,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":2500}
I20260812 06:19:20.763266  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=14.095187
I20260812 06:19:20.816457  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.053s	user 0.012s	sys 0.031s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":19307,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:20.816991  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=2.188937
I20260812 06:19:20.832697  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.015s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5992,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:20.833451  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=1.000000
I20260812 06:19:20.972478  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.139s	user 0.099s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":970,"dirs.run_cpu_time_us":1900,"dirs.run_wall_time_us":9242,"lbm_read_time_us":10031,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27068,"lbm_writes_lt_1ms":543,"mutex_wait_us":347,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:19:20.973184  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=11.118625
I20260812 06:19:21.009271  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.036s	user 0.031s	sys 0.004s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":15195,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:21.009879  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=2.188937
I20260812 06:19:21.037890  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.027s	user 0.010s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":7808,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":450}
I20260812 06:19:21.038383  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=2.188937
I20260812 06:19:21.048837  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3896,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:21.049464  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=1.000000
I20260812 06:19:21.206269  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.157s	user 0.140s	sys 0.011s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":638,"lbm_read_time_us":9955,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31128,"lbm_writes_lt_1ms":543,"mutex_wait_us":75,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":2500}
I20260812 06:19:21.207022  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=14.095187
I20260812 06:19:21.265156  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.058s	user 0.035s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23353,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:21.265679  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=2.188937
I20260812 06:19:21.277154  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.011s	user 0.004s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3988,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:21.277652  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=1.000000
I20260812 06:19:21.425290  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.147s	user 0.115s	sys 0.025s 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":727,"lbm_read_time_us":9941,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28341,"lbm_writes_lt_1ms":543,"mutex_wait_us":42,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:19:21.426105  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=14.095187
I20260812 06:19:21.485059  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.059s	user 0.040s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24319,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:21.485857  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=2.188937
I20260812 06:19:21.499974  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5542,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:21.500491  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushMRSOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=1.000000
I20260812 06:19:21.520874  7641 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.890s	user 1.811s	sys 0.126s
I20260812 06:19:21.528772  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushMRSOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.028s	user 0.023s	sys 0.004s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":236,"dirs.run_wall_time_us":1266,"drs_written":1,"lbm_read_time_us":32,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1756,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:21.529433  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling LogGCOp(7a0e327e6ae348eaa19c52fe8b89b9b8): free 132571593 bytes of WAL
I20260812 06:19:21.529666  7750 log_reader.cc:385] T 7a0e327e6ae348eaa19c52fe8b89b9b8: removed 13 log segments from log reader
I20260812 06:19:21.529731  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000029 (ops 135-139)
I20260812 06:19:21.529783  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000030 (ops 140-144)
I20260812 06:19:21.529841  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000031 (ops 145-149)
I20260812 06:19:21.529881  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000032 (ops 150-154)
I20260812 06:19:21.529918  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000033 (ops 155-159)
I20260812 06:19:21.529960  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000034 (ops 160-164)
I20260812 06:19:21.530000  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000035 (ops 165-168)
I20260812 06:19:21.530040  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000036 (ops 169-173)
I20260812 06:19:21.530079  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000037 (ops 174-178)
I20260812 06:19:21.530118  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000038 (ops 179-183)
I20260812 06:19:21.530159  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000039 (ops 184-188)
I20260812 06:19:21.530197  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000040 (ops 189-192)
I20260812 06:19:21.530237  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000041 (ops 193-197)
I20260812 06:19:21.557919  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: LogGCOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.028s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:19:21.558435  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=2.188937
I20260812 06:19:21.569543  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: FlushDeltaMemStoresOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4280,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:21.570017  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling LogGCOp(7a0e327e6ae348eaa19c52fe8b89b9b8): free 12017954 bytes of WAL
I20260812 06:19:21.570227  7750 log_reader.cc:385] T 7a0e327e6ae348eaa19c52fe8b89b9b8: removed 1 log segments from log reader
I20260812 06:19:21.570271  7750 log.cc:1079] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/7a0e327e6ae348eaa19c52fe8b89b9b8/wal-000000042 (ops 198-202)
I20260812 06:19:21.573959  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: LogGCOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:21.574308  7815 maintenance_manager.cc:419] P 805118e162074090b034168342871582: Scheduling MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8): perf score=1.000000
I20260812 06:19:21.576295  7641 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.055s	user 0.005s	sys 0.000s
I20260812 06:19:21.576953  7641 tablet_server.cc:179] TabletServer@127.7.118.65:0 shutting down...
I20260812 06:19:21.703073  7750 maintenance_manager.cc:643] P 805118e162074090b034168342871582: MajorDeltaCompactionOp(7a0e327e6ae348eaa19c52fe8b89b9b8) complete. Timing: real 0.129s	user 0.087s	sys 0.040s Metrics: {"cfile_cache_hit":532,"cfile_cache_hit_bytes":24774689,"cfile_cache_miss":101,"cfile_cache_miss_bytes":4102531,"cfile_init":3,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":825,"lbm_read_time_us":1854,"lbm_reads_lt_1ms":113,"lbm_write_time_us":28981,"lbm_writes_lt_1ms":643,"mutex_wait_us":114,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13568,"thread_start_us":89,"threads_started":1,"update_count":3000}
I20260812 06:19:21.704313  7641 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:21.704787  7641 tablet_replica.cc:333] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582: stopping tablet replica
I20260812 06:19:21.705089  7641 raft_consensus.cc:2243] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:21.705381  7641 raft_consensus.cc:2272] T 7a0e327e6ae348eaa19c52fe8b89b9b8 P 805118e162074090b034168342871582 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:21.721877  7641 tablet_server.cc:196] TabletServer@127.7.118.65:0 shutdown complete.
I20260812 06:19:21.756027  7641 master.cc:562] Master@127.7.118.126:38317 shutting down...
I20260812 06:19:21.760188  7641 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 290a327640ce4ea2bd337ecff20cb15d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:21.760386  7641 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 290a327640ce4ea2bd337ecff20cb15d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:21.760479  7641 tablet_replica.cc:333] T 00000000000000000000000000000000 P 290a327640ce4ea2bd337ecff20cb15d: stopping tablet replica
I20260812 06:19:21.772928  7641 master.cc:584] Master@127.7.118.126:38317 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5523 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:21.861709  7641 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.7.118.126:45259
I20260812 06:19:21.862130  7641 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:21.864646  7849 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:19:21.864738  7848 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:19:21.864646  7851 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:21.864807  7641 server_base.cc:1061] running on GCE node
I20260812 06:19:21.865052  7641 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:21.865116  7641 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:19:21.865141  7641 hybrid_clock.cc:648] HybridClock initialized: now 1786515561865140 us; error 0 us; skew 500 ppm
I20260812 06:19:21.865911  7641 webserver.cc:533] Webserver started at http://127.7.118.126:44849/ using document root <none> and password file <none>
I20260812 06:19:21.866084  7641 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:21.866155  7641 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:21.866261  7641 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:21.866657  7641 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/master-0-root/instance:
uuid: "a03da9ed67bb41869d68af72d5a77edb"
format_stamp: "Formatted at 2026-08-12 06:19:21 on dist-test-slave-1jjb"
I20260812 06:19:21.868227  7641 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:21.869176  7856 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:19:21.869397  7641 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:21.869486  7641 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/master-0-root
uuid: "a03da9ed67bb41869d68af72d5a77edb"
format_stamp: "Formatted at 2026-08-12 06:19:21 on dist-test-slave-1jjb"
I20260812 06:19:21.869580  7641 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-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:19:21.890113  7641 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:21.890563  7641 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:21.894986  7641 rpc_server.cc:307] RPC server started. Bound to: 127.7.118.126:45259
I20260812 06:19:21.898087  7917 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:19:21.905267  7916 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.7.118.126:45259 every 8 connection(s)
I20260812 06:19:21.907656  7917 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a03da9ed67bb41869d68af72d5a77edb: Bootstrap starting.
I20260812 06:19:21.908558  7917 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P a03da9ed67bb41869d68af72d5a77edb: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:21.909644  7917 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a03da9ed67bb41869d68af72d5a77edb: No bootstrap required, opened a new log
I20260812 06:19:21.910048  7917 raft_consensus.cc:359] T 00000000000000000000000000000000 P a03da9ed67bb41869d68af72d5a77edb [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a03da9ed67bb41869d68af72d5a77edb" member_type: VOTER }
I20260812 06:19:21.910161  7917 raft_consensus.cc:385] T 00000000000000000000000000000000 P a03da9ed67bb41869d68af72d5a77edb [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:21.910211  7917 raft_consensus.cc:740] T 00000000000000000000000000000000 P a03da9ed67bb41869d68af72d5a77edb [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a03da9ed67bb41869d68af72d5a77edb, State: Initialized, Role: FOLLOWER
I20260812 06:19:21.910408  7917 consensus_queue.cc:260] T 00000000000000000000000000000000 P a03da9ed67bb41869d68af72d5a77edb [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: "a03da9ed67bb41869d68af72d5a77edb" member_type: VOTER }
I20260812 06:19:21.910516  7917 raft_consensus.cc:399] T 00000000000000000000000000000000 P a03da9ed67bb41869d68af72d5a77edb [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:21.910567  7917 raft_consensus.cc:493] T 00000000000000000000000000000000 P a03da9ed67bb41869d68af72d5a77edb [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:21.910625  7917 raft_consensus.cc:3060] T 00000000000000000000000000000000 P a03da9ed67bb41869d68af72d5a77edb [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:21.911312  7917 raft_consensus.cc:515] T 00000000000000000000000000000000 P a03da9ed67bb41869d68af72d5a77edb [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a03da9ed67bb41869d68af72d5a77edb" member_type: VOTER }
I20260812 06:19:21.911480  7917 leader_election.cc:304] T 00000000000000000000000000000000 P a03da9ed67bb41869d68af72d5a77edb [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: a03da9ed67bb41869d68af72d5a77edb; no voters: 
I20260812 06:19:21.911679  7917 leader_election.cc:290] T 00000000000000000000000000000000 P a03da9ed67bb41869d68af72d5a77edb [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:21.911795  7920 raft_consensus.cc:2804] T 00000000000000000000000000000000 P a03da9ed67bb41869d68af72d5a77edb [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:21.912118  7920 raft_consensus.cc:697] T 00000000000000000000000000000000 P a03da9ed67bb41869d68af72d5a77edb [term 1 LEADER]: Becoming Leader. State: Replica: a03da9ed67bb41869d68af72d5a77edb, State: Running, Role: LEADER
I20260812 06:19:21.912232  7917 sys_catalog.cc:565] T 00000000000000000000000000000000 P a03da9ed67bb41869d68af72d5a77edb [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:21.912264  7920 consensus_queue.cc:237] T 00000000000000000000000000000000 P a03da9ed67bb41869d68af72d5a77edb [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: "a03da9ed67bb41869d68af72d5a77edb" member_type: VOTER }
I20260812 06:19:21.912768  7923 sys_catalog.cc:455] T 00000000000000000000000000000000 P a03da9ed67bb41869d68af72d5a77edb [sys.catalog]: SysCatalogTable state changed. Reason: New leader a03da9ed67bb41869d68af72d5a77edb. Latest consensus state: current_term: 1 leader_uuid: "a03da9ed67bb41869d68af72d5a77edb" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a03da9ed67bb41869d68af72d5a77edb" member_type: VOTER } }
I20260812 06:19:21.912744  7922 sys_catalog.cc:455] T 00000000000000000000000000000000 P a03da9ed67bb41869d68af72d5a77edb [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "a03da9ed67bb41869d68af72d5a77edb" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a03da9ed67bb41869d68af72d5a77edb" member_type: VOTER } }
I20260812 06:19:21.912878  7923 sys_catalog.cc:458] T 00000000000000000000000000000000 P a03da9ed67bb41869d68af72d5a77edb [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:21.912945  7922 sys_catalog.cc:458] T 00000000000000000000000000000000 P a03da9ed67bb41869d68af72d5a77edb [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:21.913554  7928 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:21.914193  7928 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:21.914423  7641 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:21.916100  7928 catalog_manager.cc:1383] Generated new cluster ID: 944fa785b55a4149bd29793b71b2a9b9
I20260812 06:19:21.916153  7928 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:21.921175  7928 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:21.921672  7928 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:21.927982  7928 catalog_manager.cc:6092] T 00000000000000000000000000000000 P a03da9ed67bb41869d68af72d5a77edb: Generated new TSK 0
I20260812 06:19:21.928175  7928 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:21.930614  7641 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:21.932500  7942 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:19:21.932574  7940 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:19:21.932643  7944 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:21.932780  7641 server_base.cc:1061] running on GCE node
I20260812 06:19:21.932966  7641 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:21.933027  7641 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:19:21.933079  7641 hybrid_clock.cc:648] HybridClock initialized: now 1786515561933079 us; error 0 us; skew 500 ppm
I20260812 06:19:21.933895  7641 webserver.cc:533] Webserver started at http://127.7.118.65:45125/ using document root <none> and password file <none>
I20260812 06:19:21.934088  7641 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:21.934157  7641 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:21.934260  7641 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:21.934645  7641 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root/instance:
uuid: "073fa474863e468fa68bcf07bc8d0f3e"
format_stamp: "Formatted at 2026-08-12 06:19:21 on dist-test-slave-1jjb"
I20260812 06:19:21.936058  7641 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.001s
I20260812 06:19:21.936991  7950 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:19:21.937215  7641 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:21.937302  7641 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root
uuid: "073fa474863e468fa68bcf07bc8d0f3e"
format_stamp: "Formatted at 2026-08-12 06:19:21 on dist-test-slave-1jjb"
I20260812 06:19:21.937366  7641 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-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:19:21.950948  7641 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:21.951324  7641 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:21.951628  7641 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:21.952129  7641 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:21.952185  7641 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:21.952240  7641 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:21.952289  7641 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:21.956295  7641 rpc_server.cc:307] RPC server started. Bound to: 127.7.118.65:37799
I20260812 06:19:21.957036  8020 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.7.118.65:37799 every 8 connection(s)
I20260812 06:19:21.964480  8021 heartbeater.cc:344] Connected to a master server at 127.7.118.126:45259
I20260812 06:19:21.964624  8021 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:21.964876  8021 heartbeater.cc:507] Master 127.7.118.126:45259 requested a full tablet report, sending...
I20260812 06:19:21.965559  7873 ts_manager.cc:194] Registered new tserver with Master: 073fa474863e468fa68bcf07bc8d0f3e (127.7.118.65:37799)
I20260812 06:19:21.965809  7641 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.008845292s
I20260812 06:19:21.966375  7873 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:49034
I20260812 06:19:21.972613  7873 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:49036:
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:19:21.981115  7982 tablet_service.cc:1511] Processing CreateTablet for tablet d133b58bd71545f2a91240823ce56f0f (DEFAULT_TABLE table=heavy-update-compaction-test [id=edfc82ba0aa241fe91386b2d1bdd48cd]), partition=
I20260812 06:19:21.981410  7982 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet d133b58bd71545f2a91240823ce56f0f. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:21.983275  8035 tablet_bootstrap.cc:492] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Bootstrap starting.
I20260812 06:19:21.984318  8035 tablet_bootstrap.cc:654] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:21.985270  8035 tablet_bootstrap.cc:492] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: No bootstrap required, opened a new log
I20260812 06:19:21.985340  8035 ts_tablet_manager.cc:1403] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:21.985662  8035 raft_consensus.cc:359] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "073fa474863e468fa68bcf07bc8d0f3e" member_type: VOTER last_known_addr { host: "127.7.118.65" port: 37799 } }
I20260812 06:19:21.985742  8035 raft_consensus.cc:385] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:21.985764  8035 raft_consensus.cc:740] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 073fa474863e468fa68bcf07bc8d0f3e, State: Initialized, Role: FOLLOWER
I20260812 06:19:21.985857  8035 consensus_queue.cc:260] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e [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: "073fa474863e468fa68bcf07bc8d0f3e" member_type: VOTER last_known_addr { host: "127.7.118.65" port: 37799 } }
I20260812 06:19:21.985913  8035 raft_consensus.cc:399] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:21.985934  8035 raft_consensus.cc:493] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:21.985973  8035 raft_consensus.cc:3060] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:21.986807  8035 raft_consensus.cc:515] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "073fa474863e468fa68bcf07bc8d0f3e" member_type: VOTER last_known_addr { host: "127.7.118.65" port: 37799 } }
I20260812 06:19:21.986976  8035 leader_election.cc:304] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e [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: 073fa474863e468fa68bcf07bc8d0f3e; no voters: 
I20260812 06:19:21.987201  8035 leader_election.cc:290] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:21.987331  8037 raft_consensus.cc:2804] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:21.987555  8035 ts_tablet_manager.cc:1434] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:21.987613  8021 heartbeater.cc:499] Master 127.7.118.126:45259 was elected leader, sending a full tablet report...
I20260812 06:19:21.987556  8037 raft_consensus.cc:697] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e [term 1 LEADER]: Becoming Leader. State: Replica: 073fa474863e468fa68bcf07bc8d0f3e, State: Running, Role: LEADER
I20260812 06:19:21.987807  8037 consensus_queue.cc:237] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e [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: "073fa474863e468fa68bcf07bc8d0f3e" member_type: VOTER last_known_addr { host: "127.7.118.65" port: 37799 } }
I20260812 06:19:21.989195  7873 catalog_manager.cc:5719] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e reported cstate change: term changed from 0 to 1, leader changed from <none> to 073fa474863e468fa68bcf07bc8d0f3e (127.7.118.65). New cstate: current_term: 1 leader_uuid: "073fa474863e468fa68bcf07bc8d0f3e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "073fa474863e468fa68bcf07bc8d0f3e" member_type: VOTER last_known_addr { host: "127.7.118.65" port: 37799 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:22.044147  7641 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.051s	user 0.018s	sys 0.004s
I20260812 06:19:22.207580  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushMRSOp(d133b58bd71545f2a91240823ce56f0f): perf score=23.023690
I20260812 06:19:22.370575  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushMRSOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.163s	user 0.116s	sys 0.044s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":209,"dirs.run_wall_time_us":750,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":46134,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1500}
I20260812 06:19:22.371224  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling LogGCOp(d133b58bd71545f2a91240823ce56f0f): free 20743880 bytes of WAL
I20260812 06:19:22.371444  7955 log_reader.cc:385] T d133b58bd71545f2a91240823ce56f0f: removed 2 log segments from log reader
I20260812 06:19:22.371505  7955 log.cc:1079] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/d133b58bd71545f2a91240823ce56f0f/wal-000000001 (ops 1-6)
I20260812 06:19:22.371559  7955 log.cc:1079] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/d133b58bd71545f2a91240823ce56f0f/wal-000000002 (ops 7-11)
I20260812 06:19:22.375895  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: LogGCOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:22.376262  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling UndoDeltaBlockGCOp(d133b58bd71545f2a91240823ce56f0f): 20513819 bytes on disk
I20260812 06:19:22.376685  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: UndoDeltaBlockGCOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:19:22.377063  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f): perf score=2.188937
I20260812 06:19:22.393101  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.016s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6419,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:22.393505  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling MajorDeltaCompactionOp(d133b58bd71545f2a91240823ce56f0f): perf score=1.000000
I20260812 06:19:22.541872  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: MajorDeltaCompactionOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.148s	user 0.100s	sys 0.047s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":527,"lbm_read_time_us":11727,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25354,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"thread_start_us":318,"threads_started":5,"update_count":2000}
I20260812 06:19:22.542742  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f): perf score=11.118625
I20260812 06:19:22.585647  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.041s	user 0.011s	sys 0.029s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":19510,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:22.586233  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f): perf score=2.188937
I20260812 06:19:22.601039  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.015s	user 0.011s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4859,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":25344,"update_count":450}
I20260812 06:19:22.601547  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling MajorDeltaCompactionOp(d133b58bd71545f2a91240823ce56f0f): perf score=1.000000
I20260812 06:19:22.743731  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: MajorDeltaCompactionOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.142s	user 0.080s	sys 0.057s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":350,"lbm_read_time_us":10129,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22639,"lbm_writes_lt_1ms":443,"mutex_wait_us":32,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":70016,"update_count":2000}
I20260812 06:19:22.744472  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f): perf score=14.095187
I20260812 06:19:22.793212  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.049s	user 0.020s	sys 0.027s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":23976,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:22.793810  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f): perf score=2.188937
I20260812 06:19:22.816303  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.022s	user 0.003s	sys 0.019s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4114,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:22.816939  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling MajorDeltaCompactionOp(d133b58bd71545f2a91240823ce56f0f): perf score=1.000000
I20260812 06:19:23.000900  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: MajorDeltaCompactionOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.184s	user 0.115s	sys 0.069s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":168,"lbm_read_time_us":12679,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30965,"lbm_writes_lt_1ms":543,"mutex_wait_us":91,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":2500}
I20260812 06:19:23.001575  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f): perf score=14.095187
I20260812 06:19:23.052420  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.051s	user 0.031s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22796,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:23.052942  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f): perf score=2.188937
I20260812 06:19:23.064291  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4225,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:23.064760  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling MajorDeltaCompactionOp(d133b58bd71545f2a91240823ce56f0f): perf score=1.000000
I20260812 06:19:23.246156  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: MajorDeltaCompactionOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.181s	user 0.118s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1050,"lbm_read_time_us":11138,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29045,"lbm_writes_lt_1ms":543,"mutex_wait_us":330,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":123520,"update_count":2500}
I20260812 06:19:23.246798  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f): perf score=14.095187
I20260812 06:19:23.298514  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.052s	user 0.030s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20206,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:23.299042  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f): perf score=2.188937
I20260812 06:19:23.310654  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4290,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:23.311123  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling MajorDeltaCompactionOp(d133b58bd71545f2a91240823ce56f0f): perf score=1.000000
I20260812 06:19:23.479843  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: MajorDeltaCompactionOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.169s	user 0.119s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":162,"lbm_read_time_us":11519,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30891,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14464,"update_count":2500}
I20260812 06:19:23.480552  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f): perf score=14.095187
I20260812 06:19:23.529861  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.049s	user 0.028s	sys 0.015s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20123,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:23.530378  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f): perf score=2.188937
I20260812 06:19:23.541574  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.011s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4094,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:23.542093  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushMRSOp(d133b58bd71545f2a91240823ce56f0f): perf score=1.000000
I20260812 06:19:23.571571  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushMRSOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.029s	user 0.027s	sys 0.001s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":231,"dirs.run_wall_time_us":1289,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1599,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:23.572280  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling LogGCOp(d133b58bd71545f2a91240823ce56f0f): free 112239306 bytes of WAL
I20260812 06:19:23.572539  7955 log_reader.cc:385] T d133b58bd71545f2a91240823ce56f0f: removed 11 log segments from log reader
I20260812 06:19:23.572582  7955 log.cc:1079] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/d133b58bd71545f2a91240823ce56f0f/wal-000000003 (ops 12-16)
I20260812 06:19:23.572610  7955 log.cc:1079] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/d133b58bd71545f2a91240823ce56f0f/wal-000000004 (ops 17-20)
I20260812 06:19:23.572675  7955 log.cc:1079] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/d133b58bd71545f2a91240823ce56f0f/wal-000000005 (ops 21-25)
I20260812 06:19:23.572732  7955 log.cc:1079] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/d133b58bd71545f2a91240823ce56f0f/wal-000000006 (ops 26-30)
I20260812 06:19:23.572770  7955 log.cc:1079] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/d133b58bd71545f2a91240823ce56f0f/wal-000000007 (ops 31-35)
I20260812 06:19:23.572808  7955 log.cc:1079] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/d133b58bd71545f2a91240823ce56f0f/wal-000000008 (ops 36-40)
I20260812 06:19:23.572846  7955 log.cc:1079] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/d133b58bd71545f2a91240823ce56f0f/wal-000000009 (ops 41-45)
I20260812 06:19:23.572896  7955 log.cc:1079] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/d133b58bd71545f2a91240823ce56f0f/wal-000000010 (ops 46-50)
I20260812 06:19:23.572925  7955 log.cc:1079] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/d133b58bd71545f2a91240823ce56f0f/wal-000000011 (ops 51-55)
I20260812 06:19:23.572959  7955 log.cc:1079] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/d133b58bd71545f2a91240823ce56f0f/wal-000000012 (ops 56-60)
I20260812 06:19:23.572999  7955 log.cc:1079] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/d133b58bd71545f2a91240823ce56f0f/wal-000000013 (ops 61-65)
I20260812 06:19:23.599323  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: LogGCOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.027s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:19:23.599861  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f): perf score=3.181125
I20260812 06:19:23.619192  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.019s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7091,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:23.619624  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling LogGCOp(d133b58bd71545f2a91240823ce56f0f): free 12017932 bytes of WAL
I20260812 06:19:23.619830  7955 log_reader.cc:385] T d133b58bd71545f2a91240823ce56f0f: removed 1 log segments from log reader
I20260812 06:19:23.619879  7955 log.cc:1079] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/d133b58bd71545f2a91240823ce56f0f/wal-000000014 (ops 66-70)
I20260812 06:19:23.622349  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: LogGCOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:23.622630  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f): perf score=2.188937
I20260812 06:19:23.643703  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.021s	user 0.005s	sys 0.012s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3527,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:23.644218  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling MajorDeltaCompactionOp(d133b58bd71545f2a91240823ce56f0f): perf score=1.000000
I20260812 06:19:23.886444  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: MajorDeltaCompactionOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.242s	user 0.170s	sys 0.064s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020730,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1018,"lbm_read_time_us":17380,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39287,"lbm_writes_lt_1ms":743,"mutex_wait_us":611,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":12416,"thread_start_us":111,"threads_started":1,"update_count":3500}
I20260812 06:19:23.887223  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f): perf score=18.063937
I20260812 06:19:23.945358  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.058s	user 0.041s	sys 0.016s Metrics: {"bytes_written":20512319,"delete_count":0,"lbm_write_time_us":25998,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:23.945779  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f): perf score=2.188937
I20260812 06:19:23.959838  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5560,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:23.960330  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling UndoDeltaBlockGCOp(d133b58bd71545f2a91240823ce56f0f): 447 bytes on disk
I20260812 06:19:23.960729  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: UndoDeltaBlockGCOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:19:23.961153  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling MajorDeltaCompactionOp(d133b58bd71545f2a91240823ce56f0f): perf score=1.000000
I20260812 06:19:24.178813  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: MajorDeltaCompactionOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.218s	user 0.148s	sys 0.060s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918101,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":320,"lbm_read_time_us":15594,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33687,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:19:24.179437  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f): perf score=18.063937
I20260812 06:19:24.257169  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.078s	user 0.043s	sys 0.020s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":29367,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:24.257652  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f): perf score=2.188937
I20260812 06:19:24.268834  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4036,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:24.269281  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling MajorDeltaCompactionOp(d133b58bd71545f2a91240823ce56f0f): perf score=1.000000
I20260812 06:19:24.497278  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: MajorDeltaCompactionOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.228s	user 0.156s	sys 0.071s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918098,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":672,"lbm_read_time_us":15601,"lbm_reads_lt_1ms":672,"lbm_write_time_us":40296,"lbm_writes_lt_1ms":643,"mutex_wait_us":389,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":18176,"update_count":3000}
I20260812 06:19:24.497932  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f): perf score=14.095187
I20260812 06:19:24.553248  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.055s	user 0.022s	sys 0.032s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26606,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:24.553754  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f): perf score=2.188937
I20260812 06:19:24.568972  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.015s	user 0.001s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5436,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:24.569980  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling MajorDeltaCompactionOp(d133b58bd71545f2a91240823ce56f0f): perf score=1.000000
I20260812 06:19:24.753077  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: MajorDeltaCompactionOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.183s	user 0.142s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":785,"lbm_read_time_us":10628,"lbm_reads_lt_1ms":564,"lbm_write_time_us":33984,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2500}
I20260812 06:19:24.753818  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f): perf score=14.095187
I20260812 06:19:24.814227  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.060s	user 0.013s	sys 0.038s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23503,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:24.814838  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f): perf score=2.188937
I20260812 06:19:24.832196  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.017s	user 0.010s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6743,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:24.832742  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling MajorDeltaCompactionOp(d133b58bd71545f2a91240823ce56f0f): perf score=1.000000
I20260812 06:19:25.019747  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: MajorDeltaCompactionOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.187s	user 0.145s	sys 0.038s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":182,"lbm_read_time_us":13598,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30859,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2500}
I20260812 06:19:25.020486  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f): perf score=14.095187
I20260812 06:19:25.077049  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.056s	user 0.033s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19591,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:25.077571  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f): perf score=2.188937
I20260812 06:19:25.088899  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4138,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:25.089509  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushMRSOp(d133b58bd71545f2a91240823ce56f0f): perf score=1.000000
I20260812 06:19:25.128494  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushMRSOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.039s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":213,"dirs.run_wall_time_us":1282,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1530,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:25.129230  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling LogGCOp(d133b58bd71545f2a91240823ce56f0f): free 112239316 bytes of WAL
I20260812 06:19:25.129498  7955 log_reader.cc:385] T d133b58bd71545f2a91240823ce56f0f: removed 11 log segments from log reader
I20260812 06:19:25.129563  7955 log.cc:1079] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/d133b58bd71545f2a91240823ce56f0f/wal-000000015 (ops 71-75)
I20260812 06:19:25.129601  7955 log.cc:1079] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/d133b58bd71545f2a91240823ce56f0f/wal-000000016 (ops 76-80)
I20260812 06:19:25.129632  7955 log.cc:1079] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/d133b58bd71545f2a91240823ce56f0f/wal-000000017 (ops 81-84)
I20260812 06:19:25.129662  7955 log.cc:1079] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/d133b58bd71545f2a91240823ce56f0f/wal-000000018 (ops 85-89)
I20260812 06:19:25.129693  7955 log.cc:1079] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/d133b58bd71545f2a91240823ce56f0f/wal-000000019 (ops 90-94)
I20260812 06:19:25.129724  7955 log.cc:1079] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/d133b58bd71545f2a91240823ce56f0f/wal-000000020 (ops 95-99)
I20260812 06:19:25.129753  7955 log.cc:1079] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/d133b58bd71545f2a91240823ce56f0f/wal-000000021 (ops 100-104)
I20260812 06:19:25.129788  7955 log.cc:1079] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/d133b58bd71545f2a91240823ce56f0f/wal-000000022 (ops 105-109)
I20260812 06:19:25.129822  7955 log.cc:1079] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/d133b58bd71545f2a91240823ce56f0f/wal-000000023 (ops 110-114)
I20260812 06:19:25.129848  7955 log.cc:1079] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/d133b58bd71545f2a91240823ce56f0f/wal-000000024 (ops 115-119)
I20260812 06:19:25.129875  7955 log.cc:1079] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/d133b58bd71545f2a91240823ce56f0f/wal-000000025 (ops 120-124)
I20260812 06:19:25.160174  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: LogGCOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.031s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:19:25.160571  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f): perf score=2.188937
I20260812 06:19:25.185760  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.025s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4876,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:25.186250  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f): perf score=2.188937
I20260812 06:19:25.198627  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4438,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:25.199254  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling MajorDeltaCompactionOp(d133b58bd71545f2a91240823ce56f0f): perf score=1.000000
I20260812 06:19:25.435211  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: MajorDeltaCompactionOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.236s	user 0.157s	sys 0.069s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020745,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":233,"lbm_read_time_us":15679,"lbm_reads_lt_1ms":774,"lbm_write_time_us":38225,"lbm_writes_lt_1ms":743,"mutex_wait_us":43,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":7424,"thread_start_us":76,"threads_started":1,"update_count":3500}
I20260812 06:19:25.436136  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f): perf score=18.063937
I20260812 06:19:25.496546  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.060s	user 0.029s	sys 0.025s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":25173,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:25.497063  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling UndoDeltaBlockGCOp(d133b58bd71545f2a91240823ce56f0f): 463 bytes on disk
I20260812 06:19:25.497463  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: UndoDeltaBlockGCOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:19:25.497948  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f): perf score=2.188937
I20260812 06:19:25.509825  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4055,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:25.510458  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling MajorDeltaCompactionOp(d133b58bd71545f2a91240823ce56f0f): perf score=1.000000
I20260812 06:19:25.709623  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: MajorDeltaCompactionOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.199s	user 0.141s	sys 0.056s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918097,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":493,"lbm_read_time_us":14389,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35857,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3000}
I20260812 06:19:25.710352  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f): perf score=15.087375
I20260812 06:19:25.761972  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.051s	user 0.034s	sys 0.016s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":22872,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:25.762585  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f): perf score=2.188937
I20260812 06:19:25.780267  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.017s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5164,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:25.780795  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling MajorDeltaCompactionOp(d133b58bd71545f2a91240823ce56f0f): perf score=1.000000
I20260812 06:19:25.939286  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: MajorDeltaCompactionOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.158s	user 0.114s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815671,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":271,"lbm_read_time_us":10210,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30279,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18048,"update_count":2500}
I20260812 06:19:25.940052  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f): perf score=14.095187
I20260812 06:19:25.991039  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.051s	user 0.023s	sys 0.021s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21414,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:25.991659  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling MajorDeltaCompactionOp(d133b58bd71545f2a91240823ce56f0f): perf score=1.000000
I20260812 06:19:26.132583  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: MajorDeltaCompactionOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.141s	user 0.094s	sys 0.044s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713154,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":192,"lbm_read_time_us":9973,"lbm_reads_lt_1ms":463,"lbm_write_time_us":24077,"lbm_writes_lt_1ms":443,"mutex_wait_us":19,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2000}
I20260812 06:19:26.133311  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f): perf score=14.095187
I20260812 06:19:26.184803  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.051s	user 0.032s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21937,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:26.185309  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f): perf score=2.188937
I20260812 06:19:26.196748  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4202,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:26.197253  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling MajorDeltaCompactionOp(d133b58bd71545f2a91240823ce56f0f): perf score=1.000000
I20260812 06:19:26.381808  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: MajorDeltaCompactionOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.184s	user 0.105s	sys 0.069s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":150,"lbm_read_time_us":11844,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27452,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2500}
I20260812 06:19:26.382588  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f): perf score=14.095187
I20260812 06:19:26.433861  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.051s	user 0.030s	sys 0.011s Metrics: {"bytes_written":16409937,"delete_count":0,"lbm_write_time_us":19362,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:26.434448  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f): perf score=2.188937
I20260812 06:19:26.450397  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.016s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6000,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:26.451050  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling MajorDeltaCompactionOp(d133b58bd71545f2a91240823ce56f0f): perf score=1.000000
I20260812 06:19:26.598788  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: MajorDeltaCompactionOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.148s	user 0.103s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815719,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":977,"lbm_read_time_us":11635,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27754,"lbm_writes_lt_1ms":543,"mutex_wait_us":312,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5760,"update_count":2500}
I20260812 06:19:26.599565  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f): perf score=10.126437
I20260812 06:19:26.630617  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.031s	user 0.025s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13364,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:26.631135  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f): perf score=2.188937
I20260812 06:19:26.646677  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5601,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:26.647219  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushMRSOp(d133b58bd71545f2a91240823ce56f0f): perf score=1.000000
I20260812 06:19:26.676780  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushMRSOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.029s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":188,"dirs.run_wall_time_us":1432,"drs_written":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1865,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:26.677474  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling LogGCOp(d133b58bd71545f2a91240823ce56f0f): free 133024628 bytes of WAL
I20260812 06:19:26.677753  7955 log_reader.cc:385] T d133b58bd71545f2a91240823ce56f0f: removed 13 log segments from log reader
I20260812 06:19:26.677825  7955 log.cc:1079] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/d133b58bd71545f2a91240823ce56f0f/wal-000000026 (ops 125-129)
I20260812 06:19:26.677902  7955 log.cc:1079] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/d133b58bd71545f2a91240823ce56f0f/wal-000000027 (ops 130-134)
I20260812 06:19:26.677985  7955 log.cc:1079] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/d133b58bd71545f2a91240823ce56f0f/wal-000000028 (ops 135-139)
I20260812 06:19:26.678052  7955 log.cc:1079] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/d133b58bd71545f2a91240823ce56f0f/wal-000000029 (ops 140-144)
I20260812 06:19:26.678095  7955 log.cc:1079] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/d133b58bd71545f2a91240823ce56f0f/wal-000000030 (ops 145-149)
I20260812 06:19:26.678136  7955 log.cc:1079] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/d133b58bd71545f2a91240823ce56f0f/wal-000000031 (ops 150-154)
I20260812 06:19:26.678184  7955 log.cc:1079] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/d133b58bd71545f2a91240823ce56f0f/wal-000000032 (ops 155-159)
I20260812 06:19:26.678236  7955 log.cc:1079] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/d133b58bd71545f2a91240823ce56f0f/wal-000000033 (ops 160-164)
I20260812 06:19:26.678272  7955 log.cc:1079] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/d133b58bd71545f2a91240823ce56f0f/wal-000000034 (ops 165-169)
I20260812 06:19:26.678313  7955 log.cc:1079] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/d133b58bd71545f2a91240823ce56f0f/wal-000000035 (ops 170-174)
I20260812 06:19:26.678345  7955 log.cc:1079] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/d133b58bd71545f2a91240823ce56f0f/wal-000000036 (ops 175-179)
I20260812 06:19:26.678390  7955 log.cc:1079] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/d133b58bd71545f2a91240823ce56f0f/wal-000000037 (ops 180-184)
I20260812 06:19:26.678431  7955 log.cc:1079] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: Deleting log segment in path: /tmp/dist-test-taskqQ3oDp/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515556327843-7641-0/minicluster-data/ts-0-root/wals/d133b58bd71545f2a91240823ce56f0f/wal-000000038 (ops 185-188)
I20260812 06:19:26.709084  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: LogGCOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:19:26.709538  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling UndoDeltaBlockGCOp(d133b58bd71545f2a91240823ce56f0f): 482 bytes on disk
I20260812 06:19:26.709965  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: UndoDeltaBlockGCOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:19:26.710476  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f): perf score=6.157687
I20260812 06:19:26.735260  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.025s	user 0.014s	sys 0.007s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":10644,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:19:26.735742  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling MajorDeltaCompactionOp(d133b58bd71545f2a91240823ce56f0f): perf score=1.000000
I20260812 06:19:26.951507  7641 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.907s	user 1.803s	sys 0.173s
I20260812 06:19:26.953871  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: MajorDeltaCompactionOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.218s	user 0.119s	sys 0.086s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918216,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":152,"lbm_read_time_us":13948,"lbm_reads_lt_1ms":665,"lbm_write_time_us":33617,"lbm_writes_lt_1ms":643,"mutex_wait_us":28,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":28160,"thread_start_us":89,"threads_started":1,"update_count":3000}
I20260812 06:19:26.954406  8022 maintenance_manager.cc:419] P 073fa474863e468fa68bcf07bc8d0f3e: Scheduling FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f): perf score=18.063937
I20260812 06:19:26.987478  7641 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.035s	user 0.001s	sys 0.000s
I20260812 06:19:26.988116  7641 tablet_server.cc:179] TabletServer@127.7.118.65:0 shutting down...
I20260812 06:19:27.014133  7955 maintenance_manager.cc:643] P 073fa474863e468fa68bcf07bc8d0f3e: FlushDeltaMemStoresOp(d133b58bd71545f2a91240823ce56f0f) complete. Timing: real 0.060s	user 0.037s	sys 0.020s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":26857,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:27.014684  7641 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:27.014938  7641 tablet_replica.cc:333] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e: stopping tablet replica
I20260812 06:19:27.015125  7641 raft_consensus.cc:2243] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:27.015349  7641 raft_consensus.cc:2272] T d133b58bd71545f2a91240823ce56f0f P 073fa474863e468fa68bcf07bc8d0f3e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:27.018945  7641 tablet_server.cc:196] TabletServer@127.7.118.65:0 shutdown complete.
I20260812 06:19:27.021808  7641 master.cc:562] Master@127.7.118.126:45259 shutting down...
I20260812 06:19:27.026757  7641 raft_consensus.cc:2243] T 00000000000000000000000000000000 P a03da9ed67bb41869d68af72d5a77edb [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:27.026907  7641 raft_consensus.cc:2272] T 00000000000000000000000000000000 P a03da9ed67bb41869d68af72d5a77edb [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:27.026964  7641 tablet_replica.cc:333] T 00000000000000000000000000000000 P a03da9ed67bb41869d68af72d5a77edb: stopping tablet replica
I20260812 06:19:27.039371  7641 master.cc:584] Master@127.7.118.126:45259 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5270 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10795 ms total)

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