[==========] 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:53.783720  2502 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.2.113.190:33441
I20260812 06:19:53.784718  2502 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:53.785326  2502 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:53.791714  2510 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:53.791889  2502 server_base.cc:1061] running on GCE node
W20260812 06:19:53.791785  2508 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:53.792007  2512 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:53.792542  2502 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:53.792666  2502 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:53.792713  2502 hybrid_clock.cc:648] HybridClock initialized: now 1786515593792711 us; error 0 us; skew 500 ppm
I20260812 06:19:53.794479  2502 webserver.cc:533] Webserver started at http://127.2.113.190:43313/ using document root <none> and password file <none>
I20260812 06:19:53.795090  2502 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:53.795161  2502 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:53.795425  2502 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:53.797116  2502 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/master-0-root/instance:
uuid: "800be48d36c34c2c85d4c6a597743d06"
format_stamp: "Formatted at 2026-08-12 06:19:53 on dist-test-slave-pgkr"
I20260812 06:19:53.800685  2502 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:19:53.802775  2518 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:53.803838  2502 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:53.803975  2502 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/master-0-root
uuid: "800be48d36c34c2c85d4c6a597743d06"
format_stamp: "Formatted at 2026-08-12 06:19:53 on dist-test-slave-pgkr"
I20260812 06:19:53.804083  2502 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-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:53.817289  2502 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:53.817906  2502 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:53.818084  2502 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:53.825914  2502 rpc_server.cc:307] RPC server started. Bound to: 127.2.113.190:33441
I20260812 06:19:53.825917  2581 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.2.113.190:33441 every 8 connection(s)
I20260812 06:19:53.828243  2582 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:53.833757  2582 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 800be48d36c34c2c85d4c6a597743d06: Bootstrap starting.
I20260812 06:19:53.836346  2582 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 800be48d36c34c2c85d4c6a597743d06: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:53.837363  2582 log.cc:826] T 00000000000000000000000000000000 P 800be48d36c34c2c85d4c6a597743d06: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:53.839246  2582 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 800be48d36c34c2c85d4c6a597743d06: No bootstrap required, opened a new log
I20260812 06:19:53.842146  2582 raft_consensus.cc:359] T 00000000000000000000000000000000 P 800be48d36c34c2c85d4c6a597743d06 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "800be48d36c34c2c85d4c6a597743d06" member_type: VOTER }
I20260812 06:19:53.842363  2582 raft_consensus.cc:385] T 00000000000000000000000000000000 P 800be48d36c34c2c85d4c6a597743d06 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:53.842478  2582 raft_consensus.cc:740] T 00000000000000000000000000000000 P 800be48d36c34c2c85d4c6a597743d06 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 800be48d36c34c2c85d4c6a597743d06, State: Initialized, Role: FOLLOWER
I20260812 06:19:53.843155  2582 consensus_queue.cc:260] T 00000000000000000000000000000000 P 800be48d36c34c2c85d4c6a597743d06 [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: "800be48d36c34c2c85d4c6a597743d06" member_type: VOTER }
I20260812 06:19:53.843338  2582 raft_consensus.cc:399] T 00000000000000000000000000000000 P 800be48d36c34c2c85d4c6a597743d06 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:53.843427  2582 raft_consensus.cc:493] T 00000000000000000000000000000000 P 800be48d36c34c2c85d4c6a597743d06 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:53.843555  2582 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 800be48d36c34c2c85d4c6a597743d06 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:53.844388  2582 raft_consensus.cc:515] T 00000000000000000000000000000000 P 800be48d36c34c2c85d4c6a597743d06 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "800be48d36c34c2c85d4c6a597743d06" member_type: VOTER }
I20260812 06:19:53.844856  2582 leader_election.cc:304] T 00000000000000000000000000000000 P 800be48d36c34c2c85d4c6a597743d06 [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: 800be48d36c34c2c85d4c6a597743d06; no voters: 
I20260812 06:19:53.845198  2582 leader_election.cc:290] T 00000000000000000000000000000000 P 800be48d36c34c2c85d4c6a597743d06 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:53.845348  2585 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 800be48d36c34c2c85d4c6a597743d06 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:53.845625  2585 raft_consensus.cc:697] T 00000000000000000000000000000000 P 800be48d36c34c2c85d4c6a597743d06 [term 1 LEADER]: Becoming Leader. State: Replica: 800be48d36c34c2c85d4c6a597743d06, State: Running, Role: LEADER
I20260812 06:19:53.845997  2585 consensus_queue.cc:237] T 00000000000000000000000000000000 P 800be48d36c34c2c85d4c6a597743d06 [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: "800be48d36c34c2c85d4c6a597743d06" member_type: VOTER }
I20260812 06:19:53.846252  2582 sys_catalog.cc:565] T 00000000000000000000000000000000 P 800be48d36c34c2c85d4c6a597743d06 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:53.847788  2586 sys_catalog.cc:455] T 00000000000000000000000000000000 P 800be48d36c34c2c85d4c6a597743d06 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "800be48d36c34c2c85d4c6a597743d06" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "800be48d36c34c2c85d4c6a597743d06" member_type: VOTER } }
I20260812 06:19:53.847920  2586 sys_catalog.cc:458] T 00000000000000000000000000000000 P 800be48d36c34c2c85d4c6a597743d06 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:53.848258  2587 sys_catalog.cc:455] T 00000000000000000000000000000000 P 800be48d36c34c2c85d4c6a597743d06 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 800be48d36c34c2c85d4c6a597743d06. Latest consensus state: current_term: 1 leader_uuid: "800be48d36c34c2c85d4c6a597743d06" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "800be48d36c34c2c85d4c6a597743d06" member_type: VOTER } }
I20260812 06:19:53.848330  2596 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:53.848407  2587 sys_catalog.cc:458] T 00000000000000000000000000000000 P 800be48d36c34c2c85d4c6a597743d06 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:53.848649  2502 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:53.850991  2596 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:53.855609  2596 catalog_manager.cc:1383] Generated new cluster ID: 4eea59f9668c46d78ef51c3c7b768462
I20260812 06:19:53.855731  2596 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:53.875077  2596 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:53.875973  2596 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:53.882998  2596 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 800be48d36c34c2c85d4c6a597743d06: Generated new TSK 0
I20260812 06:19:53.883661  2596 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:53.913622  2502 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:53.916797  2605 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:53.916894  2608 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:53.916797  2606 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:53.917099  2502 server_base.cc:1061] running on GCE node
I20260812 06:19:53.917273  2502 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:53.917321  2502 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:53.917343  2502 hybrid_clock.cc:648] HybridClock initialized: now 1786515593917343 us; error 0 us; skew 500 ppm
I20260812 06:19:53.918336  2502 webserver.cc:533] Webserver started at http://127.2.113.129:37735/ using document root <none> and password file <none>
I20260812 06:19:53.918517  2502 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:53.918576  2502 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:53.918692  2502 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:53.919138  2502 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root/instance:
uuid: "f00b3357e0404bea991c77bfc25c0be7"
format_stamp: "Formatted at 2026-08-12 06:19:53 on dist-test-slave-pgkr"
I20260812 06:19:53.921022  2502 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:53.922183  2613 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:53.922456  2502 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:53.922534  2502 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root
uuid: "f00b3357e0404bea991c77bfc25c0be7"
format_stamp: "Formatted at 2026-08-12 06:19:53 on dist-test-slave-pgkr"
I20260812 06:19:53.922669  2502 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-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:53.942131  2502 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:53.943074  2502 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:53.943643  2502 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:53.944530  2502 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:53.944583  2502 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:53.944665  2502 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:53.944705  2502 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:53.951973  2502 rpc_server.cc:307] RPC server started. Bound to: 127.2.113.129:34671
I20260812 06:19:53.952055  2685 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.2.113.129:34671 every 8 connection(s)
I20260812 06:19:53.961809  2686 heartbeater.cc:344] Connected to a master server at 127.2.113.190:33441
I20260812 06:19:53.962072  2686 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:53.962527  2686 heartbeater.cc:507] Master 127.2.113.190:33441 requested a full tablet report, sending...
I20260812 06:19:53.964154  2537 ts_manager.cc:194] Registered new tserver with Master: f00b3357e0404bea991c77bfc25c0be7 (127.2.113.129:34671)
I20260812 06:19:53.964231  2502 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011553226s
I20260812 06:19:53.965672  2537 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:37386
I20260812 06:19:53.973646  2537 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:37396:
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:53.987627  2647 tablet_service.cc:1511] Processing CreateTablet for tablet 3b494a96e11a44c0b12d14136f60af02 (DEFAULT_TABLE table=heavy-update-compaction-test [id=117dd328f89f4200bfb1e2cd47d32eea]), partition=
I20260812 06:19:53.988101  2647 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 3b494a96e11a44c0b12d14136f60af02. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:53.990423  2701 tablet_bootstrap.cc:492] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Bootstrap starting.
I20260812 06:19:53.991793  2701 tablet_bootstrap.cc:654] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:53.993324  2701 tablet_bootstrap.cc:492] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: No bootstrap required, opened a new log
I20260812 06:19:53.993449  2701 ts_tablet_manager.cc:1403] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:53.993923  2701 raft_consensus.cc:359] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f00b3357e0404bea991c77bfc25c0be7" member_type: VOTER last_known_addr { host: "127.2.113.129" port: 34671 } }
I20260812 06:19:53.994047  2701 raft_consensus.cc:385] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:53.994097  2701 raft_consensus.cc:740] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f00b3357e0404bea991c77bfc25c0be7, State: Initialized, Role: FOLLOWER
I20260812 06:19:53.994246  2701 consensus_queue.cc:260] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7 [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: "f00b3357e0404bea991c77bfc25c0be7" member_type: VOTER last_known_addr { host: "127.2.113.129" port: 34671 } }
I20260812 06:19:53.994359  2701 raft_consensus.cc:399] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:53.994407  2701 raft_consensus.cc:493] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:53.994462  2701 raft_consensus.cc:3060] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:53.995520  2701 raft_consensus.cc:515] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f00b3357e0404bea991c77bfc25c0be7" member_type: VOTER last_known_addr { host: "127.2.113.129" port: 34671 } }
I20260812 06:19:53.995646  2701 leader_election.cc:304] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7 [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: f00b3357e0404bea991c77bfc25c0be7; no voters: 
I20260812 06:19:53.995879  2701 leader_election.cc:290] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:53.995977  2703 raft_consensus.cc:2804] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:53.996158  2703 raft_consensus.cc:697] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7 [term 1 LEADER]: Becoming Leader. State: Replica: f00b3357e0404bea991c77bfc25c0be7, State: Running, Role: LEADER
I20260812 06:19:53.996241  2701 ts_tablet_manager.cc:1434] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:53.996345  2703 consensus_queue.cc:237] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7 [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: "f00b3357e0404bea991c77bfc25c0be7" member_type: VOTER last_known_addr { host: "127.2.113.129" port: 34671 } }
I20260812 06:19:53.996508  2686 heartbeater.cc:499] Master 127.2.113.190:33441 was elected leader, sending a full tablet report...
I20260812 06:19:53.999233  2537 catalog_manager.cc:5719] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7 reported cstate change: term changed from 0 to 1, leader changed from <none> to f00b3357e0404bea991c77bfc25c0be7 (127.2.113.129). New cstate: current_term: 1 leader_uuid: "f00b3357e0404bea991c77bfc25c0be7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f00b3357e0404bea991c77bfc25c0be7" member_type: VOTER last_known_addr { host: "127.2.113.129" port: 34671 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:54.063558  2502 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.015s	sys 0.009s
I20260812 06:19:54.203147  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushMRSOp(3b494a96e11a44c0b12d14136f60af02): perf score=19.054940
I20260812 06:19:54.386680  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushMRSOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.183s	user 0.135s	sys 0.046s Metrics: {"bytes_written":13251052,"cfile_init":1,"compiler_manager_pool.queue_time_us":188,"delete_count":0,"dirs.queue_time_us":496,"dirs.run_cpu_time_us":278,"dirs.run_wall_time_us":922,"drs_written":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42801,"lbm_writes_lt_1ms":780,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":191744,"thread_start_us":120,"threads_started":1,"update_count":1615}
I20260812 06:19:54.388341  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling LogGCOp(3b494a96e11a44c0b12d14136f60af02): free 20743880 bytes of WAL
I20260812 06:19:54.388757  2619 log_reader.cc:385] T 3b494a96e11a44c0b12d14136f60af02: removed 2 log segments from log reader
I20260812 06:19:54.388947  2619 log.cc:1079] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/3b494a96e11a44c0b12d14136f60af02/wal-000000001 (ops 1-6)
I20260812 06:19:54.389083  2619 log.cc:1079] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/3b494a96e11a44c0b12d14136f60af02/wal-000000002 (ops 7-11)
I20260812 06:19:54.394814  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: LogGCOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.006s	user 0.000s	sys 0.006s Metrics: {}
I20260812 06:19:54.395241  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=2.188937
I20260812 06:19:54.427459  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.032s	user 0.007s	sys 0.012s Metrics: {"bytes_written":3569334,"delete_count":0,"lbm_write_time_us":3684,"lbm_writes_lt_1ms":90,"reinsert_count":0,"update_count":435}
I20260812 06:19:54.428007  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling UndoDeltaBlockGCOp(3b494a96e11a44c0b12d14136f60af02): 16411394 bytes on disk
I20260812 06:19:54.428789  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: UndoDeltaBlockGCOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":88,"lbm_reads_lt_1ms":4}
I20260812 06:19:54.429236  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=2.188937
I20260812 06:19:54.443231  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.014s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5455,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:54.443746  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling MajorDeltaCompactionOp(3b494a96e11a44c0b12d14136f60af02): perf score=1.000000
I20260812 06:19:54.618216  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: MajorDeltaCompactionOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.174s	user 0.106s	sys 0.068s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774791,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":975,"lbm_read_time_us":12221,"lbm_reads_lt_1ms":569,"lbm_write_time_us":28595,"lbm_writes_lt_1ms":543,"mutex_wait_us":68,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13312,"thread_start_us":350,"threads_started":5,"update_count":2500}
I20260812 06:19:54.618904  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=10.126437
I20260812 06:19:54.664654  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.046s	user 0.025s	sys 0.010s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15960,"lbm_writes_lt_1ms":303,"mutex_wait_us":3,"reinsert_count":0,"update_count":1500}
I20260812 06:19:54.665215  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=2.188937
I20260812 06:19:54.676209  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4074,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:54.676935  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling MajorDeltaCompactionOp(3b494a96e11a44c0b12d14136f60af02): perf score=1.000000
I20260812 06:19:54.807152  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: MajorDeltaCompactionOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.130s	user 0.108s	sys 0.020s 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":144,"lbm_read_time_us":8776,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26015,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":28032,"update_count":2000}
I20260812 06:19:54.807813  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=10.126437
I20260812 06:19:54.856778  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.049s	user 0.021s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17246,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:54.857214  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=2.188937
I20260812 06:19:54.868286  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4069,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:54.868947  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling MajorDeltaCompactionOp(3b494a96e11a44c0b12d14136f60af02): perf score=1.000000
I20260812 06:19:54.995433  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: MajorDeltaCompactionOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.126s	user 0.086s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":195,"lbm_read_time_us":8162,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25955,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:54.995890  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=10.126437
I20260812 06:19:55.036572  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.041s	user 0.022s	sys 0.014s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16600,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:55.037081  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=2.188937
I20260812 06:19:55.050063  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.013s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4538,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.050758  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling MajorDeltaCompactionOp(3b494a96e11a44c0b12d14136f60af02): perf score=1.000000
I20260812 06:19:55.176709  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: MajorDeltaCompactionOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.126s	user 0.098s	sys 0.027s 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":328,"lbm_read_time_us":9114,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24556,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":27648,"update_count":2000}
I20260812 06:19:55.177330  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=10.126437
I20260812 06:19:55.223346  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.046s	user 0.016s	sys 0.028s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14841,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:55.223991  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=2.188937
I20260812 06:19:55.234866  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4271,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.235436  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling MajorDeltaCompactionOp(3b494a96e11a44c0b12d14136f60af02): perf score=1.000000
I20260812 06:19:55.390106  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: MajorDeltaCompactionOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.154s	user 0.114s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1190,"lbm_read_time_us":11054,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27228,"lbm_writes_lt_1ms":443,"mutex_wait_us":364,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:55.390895  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=10.126437
I20260812 06:19:55.437922  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.047s	user 0.021s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16219,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:55.438452  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=2.188937
I20260812 06:19:55.451244  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4426,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.451887  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling MajorDeltaCompactionOp(3b494a96e11a44c0b12d14136f60af02): perf score=1.000000
I20260812 06:19:55.570749  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: MajorDeltaCompactionOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.119s	user 0.098s	sys 0.020s 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":1500,"lbm_read_time_us":8714,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22080,"lbm_writes_lt_1ms":443,"mutex_wait_us":273,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2000}
I20260812 06:19:55.571516  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=10.126437
I20260812 06:19:55.617900  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.046s	user 0.031s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19930,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:55.618424  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=2.188937
I20260812 06:19:55.632020  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4944,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.632472  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushMRSOp(3b494a96e11a44c0b12d14136f60af02): perf score=1.000000
I20260812 06:19:55.666416  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushMRSOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.034s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":258,"dirs.run_wall_time_us":1372,"drs_written":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1650,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30,"spinlock_wait_cycles":768}
I20260812 06:19:55.667512  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling LogGCOp(3b494a96e11a44c0b12d14136f60af02): free 115943181 bytes of WAL
I20260812 06:19:55.667850  2619 log_reader.cc:385] T 3b494a96e11a44c0b12d14136f60af02: removed 11 log segments from log reader
I20260812 06:19:55.667907  2619 log.cc:1079] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/3b494a96e11a44c0b12d14136f60af02/wal-000000003 (ops 12-16)
I20260812 06:19:55.667941  2619 log.cc:1079] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/3b494a96e11a44c0b12d14136f60af02/wal-000000004 (ops 17-21)
I20260812 06:19:55.667959  2619 log.cc:1079] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/3b494a96e11a44c0b12d14136f60af02/wal-000000005 (ops 22-26)
I20260812 06:19:55.668022  2619 log.cc:1079] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/3b494a96e11a44c0b12d14136f60af02/wal-000000006 (ops 27-31)
I20260812 06:19:55.668081  2619 log.cc:1079] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/3b494a96e11a44c0b12d14136f60af02/wal-000000007 (ops 32-36)
I20260812 06:19:55.668128  2619 log.cc:1079] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/3b494a96e11a44c0b12d14136f60af02/wal-000000008 (ops 37-41)
I20260812 06:19:55.668166  2619 log.cc:1079] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/3b494a96e11a44c0b12d14136f60af02/wal-000000009 (ops 42-46)
I20260812 06:19:55.668224  2619 log.cc:1079] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/3b494a96e11a44c0b12d14136f60af02/wal-000000010 (ops 47-51)
I20260812 06:19:55.668252  2619 log.cc:1079] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/3b494a96e11a44c0b12d14136f60af02/wal-000000011 (ops 52-56)
I20260812 06:19:55.668283  2619 log.cc:1079] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/3b494a96e11a44c0b12d14136f60af02/wal-000000012 (ops 57-61)
I20260812 06:19:55.668313  2619 log.cc:1079] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/3b494a96e11a44c0b12d14136f60af02/wal-000000013 (ops 62-66)
I20260812 06:19:55.694842  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: LogGCOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.027s	user 0.001s	sys 0.026s Metrics: {}
I20260812 06:19:55.695308  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling UndoDeltaBlockGCOp(3b494a96e11a44c0b12d14136f60af02): 472 bytes on disk
I20260812 06:19:55.695904  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: UndoDeltaBlockGCOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":95,"lbm_reads_lt_1ms":4}
I20260812 06:19:55.696535  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=6.157687
I20260812 06:19:55.725319  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.029s	user 0.005s	sys 0.021s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":12595,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:19:55.725872  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling LogGCOp(3b494a96e11a44c0b12d14136f60af02): free 8767118 bytes of WAL
I20260812 06:19:55.726099  2619 log_reader.cc:385] T 3b494a96e11a44c0b12d14136f60af02: removed 1 log segments from log reader
I20260812 06:19:55.726151  2619 log.cc:1079] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/3b494a96e11a44c0b12d14136f60af02/wal-000000014 (ops 67-71)
I20260812 06:19:55.728554  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: LogGCOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:55.728881  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling MajorDeltaCompactionOp(3b494a96e11a44c0b12d14136f60af02): perf score=1.000000
I20260812 06:19:55.897431  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: MajorDeltaCompactionOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.168s	user 0.120s	sys 0.046s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877221,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":719,"lbm_read_time_us":10379,"lbm_reads_lt_1ms":665,"lbm_write_time_us":35333,"lbm_writes_lt_1ms":643,"mutex_wait_us":327,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2816,"thread_start_us":79,"threads_started":1,"update_count":3000}
I20260812 06:19:55.898108  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=14.095187
I20260812 06:19:55.949469  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.051s	user 0.024s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19891,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:55.950029  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=2.188937
I20260812 06:19:55.962347  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4397,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.962918  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling MajorDeltaCompactionOp(3b494a96e11a44c0b12d14136f60af02): perf score=1.000000
I20260812 06:19:56.131901  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: MajorDeltaCompactionOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.169s	user 0.122s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":583,"lbm_read_time_us":10088,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32303,"lbm_writes_lt_1ms":543,"mutex_wait_us":158,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:19:56.132625  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=14.095187
I20260812 06:19:56.185461  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.053s	user 0.031s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20811,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:56.186049  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling MajorDeltaCompactionOp(3b494a96e11a44c0b12d14136f60af02): perf score=1.000000
I20260812 06:19:56.358862  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: MajorDeltaCompactionOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.173s	user 0.117s	sys 0.043s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":2155,"lbm_read_time_us":11076,"lbm_reads_lt_1ms":463,"lbm_write_time_us":29343,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":2000}
I20260812 06:19:56.359717  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=14.095187
I20260812 06:19:56.411438  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.051s	user 0.030s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20589,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:56.411933  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=2.188937
I20260812 06:19:56.425781  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.014s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4674,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:56.426328  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling MajorDeltaCompactionOp(3b494a96e11a44c0b12d14136f60af02): perf score=1.000000
I20260812 06:19:56.722641  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: MajorDeltaCompactionOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.296s	user 0.195s	sys 0.089s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1175,"lbm_read_time_us":14661,"lbm_reads_lt_1ms":568,"lbm_write_time_us":62359,"lbm_writes_lt_1ms":543,"mutex_wait_us":11,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2500}
I20260812 06:19:56.725658  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=11.118625
I20260812 06:19:56.837061  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.111s	user 0.062s	sys 0.028s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":41636,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:19:56.837698  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=6.157687
I20260812 06:19:56.881913  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.044s	user 0.036s	sys 0.004s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":19852,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:19:56.882468  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling MajorDeltaCompactionOp(3b494a96e11a44c0b12d14136f60af02): perf score=1.000000
I20260812 06:19:57.042773  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: MajorDeltaCompactionOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.160s	user 0.145s	sys 0.015s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774695,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":235,"lbm_read_time_us":10555,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31580,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:19:57.043453  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=14.095187
I20260812 06:19:57.096091  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.052s	user 0.024s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20771,"lbm_writes_lt_1ms":403,"mutex_wait_us":43,"reinsert_count":0,"update_count":2000}
I20260812 06:19:57.096635  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=2.188937
I20260812 06:19:57.111307  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.014s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6050,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.111792  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling MajorDeltaCompactionOp(3b494a96e11a44c0b12d14136f60af02): perf score=1.000000
I20260812 06:19:57.264129  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: MajorDeltaCompactionOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.151s	user 0.122s	sys 0.023s 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":123,"lbm_read_time_us":10962,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29347,"lbm_writes_lt_1ms":543,"mutex_wait_us":53,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:57.264810  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=14.095187
I20260812 06:19:57.324568  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.060s	user 0.048s	sys 0.007s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26325,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:57.325006  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=2.188937
I20260812 06:19:57.335740  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3866,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.336378  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushMRSOp(3b494a96e11a44c0b12d14136f60af02): perf score=1.000000
I20260812 06:19:57.368093  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushMRSOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.032s	user 0.026s	sys 0.004s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":195,"dirs.run_wall_time_us":1355,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1593,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:57.368834  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling LogGCOp(3b494a96e11a44c0b12d14136f60af02): free 120100330 bytes of WAL
I20260812 06:19:57.369056  2619 log_reader.cc:385] T 3b494a96e11a44c0b12d14136f60af02: removed 12 log segments from log reader
I20260812 06:19:57.369102  2619 log.cc:1079] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/3b494a96e11a44c0b12d14136f60af02/wal-000000015 (ops 72-76)
I20260812 06:19:57.369130  2619 log.cc:1079] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/3b494a96e11a44c0b12d14136f60af02/wal-000000016 (ops 77-81)
I20260812 06:19:57.369194  2619 log.cc:1079] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/3b494a96e11a44c0b12d14136f60af02/wal-000000017 (ops 82-86)
I20260812 06:19:57.369254  2619 log.cc:1079] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/3b494a96e11a44c0b12d14136f60af02/wal-000000018 (ops 87-90)
I20260812 06:19:57.369294  2619 log.cc:1079] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/3b494a96e11a44c0b12d14136f60af02/wal-000000019 (ops 91-95)
I20260812 06:19:57.369336  2619 log.cc:1079] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/3b494a96e11a44c0b12d14136f60af02/wal-000000020 (ops 96-100)
I20260812 06:19:57.369379  2619 log.cc:1079] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/3b494a96e11a44c0b12d14136f60af02/wal-000000021 (ops 101-105)
I20260812 06:19:57.369419  2619 log.cc:1079] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/3b494a96e11a44c0b12d14136f60af02/wal-000000022 (ops 106-110)
I20260812 06:19:57.369457  2619 log.cc:1079] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/3b494a96e11a44c0b12d14136f60af02/wal-000000023 (ops 111-114)
I20260812 06:19:57.369495  2619 log.cc:1079] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/3b494a96e11a44c0b12d14136f60af02/wal-000000024 (ops 115-119)
I20260812 06:19:57.369534  2619 log.cc:1079] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/3b494a96e11a44c0b12d14136f60af02/wal-000000025 (ops 120-124)
I20260812 06:19:57.369572  2619 log.cc:1079] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/3b494a96e11a44c0b12d14136f60af02/wal-000000026 (ops 125-128)
I20260812 06:19:57.397991  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: LogGCOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.029s	user 0.003s	sys 0.023s Metrics: {}
I20260812 06:19:57.398417  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=3.181125
I20260812 06:19:57.415706  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.017s	user 0.010s	sys 0.006s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":6843,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:57.416249  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=2.188937
I20260812 06:19:57.429409  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5272,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:57.430033  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling MajorDeltaCompactionOp(3b494a96e11a44c0b12d14136f60af02): perf score=1.000000
I20260812 06:19:57.654937  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: MajorDeltaCompactionOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.225s	user 0.148s	sys 0.072s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979737,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":705,"lbm_read_time_us":15333,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39091,"lbm_writes_lt_1ms":743,"mutex_wait_us":74,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":4096,"thread_start_us":90,"threads_started":1,"update_count":3500}
I20260812 06:19:57.657951  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling UndoDeltaBlockGCOp(3b494a96e11a44c0b12d14136f60af02): 472 bytes on disk
I20260812 06:19:57.658581  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: UndoDeltaBlockGCOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":103,"lbm_reads_lt_1ms":4}
I20260812 06:19:57.659255  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=14.095187
I20260812 06:19:57.723577  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.064s	user 0.033s	sys 0.030s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24246,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:57.724206  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=2.188937
I20260812 06:19:57.735513  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.011s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4455,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.735950  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling MajorDeltaCompactionOp(3b494a96e11a44c0b12d14136f60af02): perf score=1.000000
I20260812 06:19:57.906172  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: MajorDeltaCompactionOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.170s	user 0.115s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":683,"lbm_read_time_us":12602,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30640,"lbm_writes_lt_1ms":543,"mutex_wait_us":268,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2500}
I20260812 06:19:57.906854  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=10.126437
I20260812 06:19:57.940121  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.032s	user 0.019s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13776,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:57.940718  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=2.188937
I20260812 06:19:57.957260  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.016s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5994,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.957897  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling MajorDeltaCompactionOp(3b494a96e11a44c0b12d14136f60af02): perf score=1.000000
I20260812 06:19:58.116334  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: MajorDeltaCompactionOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.158s	user 0.111s	sys 0.043s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":334,"lbm_read_time_us":8261,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26133,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":2000}
I20260812 06:19:58.116994  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=10.126437
I20260812 06:19:58.161654  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.044s	user 0.020s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20454,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:19:58.162133  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=2.188937
I20260812 06:19:58.184180  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.022s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5910,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.184641  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=2.188937
I20260812 06:19:58.195174  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4010,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.195647  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling MajorDeltaCompactionOp(3b494a96e11a44c0b12d14136f60af02): perf score=1.000000
I20260812 06:19:58.354658  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: MajorDeltaCompactionOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.159s	user 0.127s	sys 0.031s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774807,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1249,"lbm_read_time_us":11473,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31431,"lbm_writes_lt_1ms":543,"mutex_wait_us":471,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2500}
I20260812 06:19:58.356980  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=11.118625
I20260812 06:19:58.392969  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.036s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15388,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:58.393788  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=2.188937
I20260812 06:19:58.410073  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.016s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6651,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:58.410547  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling MajorDeltaCompactionOp(3b494a96e11a44c0b12d14136f60af02): perf score=1.000000
I20260812 06:19:58.557159  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: MajorDeltaCompactionOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.146s	user 0.117s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":778,"lbm_read_time_us":8632,"lbm_reads_lt_1ms":464,"lbm_write_time_us":31145,"lbm_writes_lt_1ms":443,"mutex_wait_us":336,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:58.557749  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=11.118625
I20260812 06:19:58.601013  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.043s	user 0.028s	sys 0.007s Metrics: {"bytes_written":12717738,"delete_count":0,"lbm_write_time_us":15746,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:58.601871  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=2.188937
I20260812 06:19:58.619719  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.018s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4957,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.620268  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=2.188937
I20260812 06:19:58.630277  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3834,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:58.630867  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling MajorDeltaCompactionOp(3b494a96e11a44c0b12d14136f60af02): perf score=1.000000
I20260812 06:19:58.807821  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: MajorDeltaCompactionOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.177s	user 0.120s	sys 0.045s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774802,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":267,"lbm_read_time_us":13702,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30860,"lbm_writes_lt_1ms":543,"mutex_wait_us":45,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17024,"update_count":2500}
I20260812 06:19:58.808638  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=14.095187
I20260812 06:19:58.864614  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.056s	user 0.022s	sys 0.023s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":17706,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:58.865331  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=2.188937
I20260812 06:19:58.877378  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.012s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4222,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.877911  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushMRSOp(3b494a96e11a44c0b12d14136f60af02): perf score=1.000000
I20260812 06:19:58.911929  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushMRSOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.034s	user 0.024s	sys 0.004s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":191,"dirs.run_wall_time_us":1391,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1438,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:58.912744  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling LogGCOp(3b494a96e11a44c0b12d14136f60af02): free 121006692 bytes of WAL
I20260812 06:19:58.913004  2619 log_reader.cc:385] T 3b494a96e11a44c0b12d14136f60af02: removed 12 log segments from log reader
I20260812 06:19:58.913074  2619 log.cc:1079] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/3b494a96e11a44c0b12d14136f60af02/wal-000000027 (ops 129-133)
I20260812 06:19:58.913131  2619 log.cc:1079] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/3b494a96e11a44c0b12d14136f60af02/wal-000000028 (ops 134-138)
I20260812 06:19:58.913190  2619 log.cc:1079] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/3b494a96e11a44c0b12d14136f60af02/wal-000000029 (ops 139-143)
I20260812 06:19:58.913233  2619 log.cc:1079] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/3b494a96e11a44c0b12d14136f60af02/wal-000000030 (ops 144-148)
I20260812 06:19:58.913270  2619 log.cc:1079] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/3b494a96e11a44c0b12d14136f60af02/wal-000000031 (ops 149-153)
I20260812 06:19:58.913309  2619 log.cc:1079] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/3b494a96e11a44c0b12d14136f60af02/wal-000000032 (ops 154-158)
I20260812 06:19:58.913347  2619 log.cc:1079] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/3b494a96e11a44c0b12d14136f60af02/wal-000000033 (ops 159-163)
I20260812 06:19:58.913386  2619 log.cc:1079] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/3b494a96e11a44c0b12d14136f60af02/wal-000000034 (ops 164-168)
I20260812 06:19:58.913424  2619 log.cc:1079] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/3b494a96e11a44c0b12d14136f60af02/wal-000000035 (ops 169-173)
I20260812 06:19:58.913461  2619 log.cc:1079] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/3b494a96e11a44c0b12d14136f60af02/wal-000000036 (ops 174-178)
I20260812 06:19:58.913501  2619 log.cc:1079] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/3b494a96e11a44c0b12d14136f60af02/wal-000000037 (ops 179-182)
I20260812 06:19:58.913540  2619 log.cc:1079] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/3b494a96e11a44c0b12d14136f60af02/wal-000000038 (ops 183-187)
I20260812 06:19:58.940366  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: LogGCOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:58.940852  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=2.188937
I20260812 06:19:58.964136  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.021s	user 0.007s	sys 0.009s Metrics: {"bytes_written":4471876,"delete_count":0,"lbm_write_time_us":7292,"lbm_writes_lt_1ms":112,"reinsert_count":0,"update_count":545}
I20260812 06:19:58.964599  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling UndoDeltaBlockGCOp(3b494a96e11a44c0b12d14136f60af02): 472 bytes on disk
I20260812 06:19:58.964983  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: UndoDeltaBlockGCOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4}
I20260812 06:19:58.965483  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=2.188937
I20260812 06:19:58.975288  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3733433,"delete_count":0,"lbm_write_time_us":3702,"lbm_writes_lt_1ms":94,"reinsert_count":0,"update_count":455}
I20260812 06:19:58.975715  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling MajorDeltaCompactionOp(3b494a96e11a44c0b12d14136f60af02): perf score=1.000000
I20260812 06:19:59.148600  2502 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.085s	user 1.909s	sys 0.118s
I20260812 06:19:59.176462  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: MajorDeltaCompactionOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.201s	user 0.138s	sys 0.060s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979743,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":15223,"lbm_reads_lt_1ms":770,"lbm_write_time_us":35654,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3500}
I20260812 06:19:59.176944  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02): perf score=14.095187
I20260812 06:19:59.213034  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: FlushDeltaMemStoresOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.036s	user 0.025s	sys 0.009s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":15140,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:59.213599  2688 maintenance_manager.cc:419] P f00b3357e0404bea991c77bfc25c0be7: Scheduling MajorDeltaCompactionOp(3b494a96e11a44c0b12d14136f60af02): perf score=1.000000
I20260812 06:19:59.221572  2502 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.072s	user 0.003s	sys 0.000s
I20260812 06:19:59.222352  2502 tablet_server.cc:179] TabletServer@127.2.113.129:0 shutting down...
I20260812 06:19:59.329977  2619 maintenance_manager.cc:643] P f00b3357e0404bea991c77bfc25c0be7: MajorDeltaCompactionOp(3b494a96e11a44c0b12d14136f60af02) complete. Timing: real 0.116s	user 0.086s	sys 0.029s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":976,"lbm_read_time_us":8202,"lbm_reads_lt_1ms":467,"lbm_write_time_us":23735,"lbm_writes_lt_1ms":443,"mutex_wait_us":93,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:59.330695  2502 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:59.331336  2502 tablet_replica.cc:333] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7: stopping tablet replica
I20260812 06:19:59.331631  2502 raft_consensus.cc:2243] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:59.331897  2502 raft_consensus.cc:2272] T 3b494a96e11a44c0b12d14136f60af02 P f00b3357e0404bea991c77bfc25c0be7 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:59.348495  2502 tablet_server.cc:196] TabletServer@127.2.113.129:0 shutdown complete.
I20260812 06:19:59.371253  2502 master.cc:562] Master@127.2.113.190:33441 shutting down...
I20260812 06:19:59.375706  2502 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 800be48d36c34c2c85d4c6a597743d06 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:59.375888  2502 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 800be48d36c34c2c85d4c6a597743d06 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:59.375943  2502 tablet_replica.cc:333] T 00000000000000000000000000000000 P 800be48d36c34c2c85d4c6a597743d06: stopping tablet replica
I20260812 06:19:59.388463  2502 master.cc:584] Master@127.2.113.190:33441 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5697 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:59.493718  2502 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.2.113.190:35369
I20260812 06:19:59.494095  2502 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:59.496521  2725 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:59.496501  2727 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:59.496654  2502 server_base.cc:1061] running on GCE node
W20260812 06:19:59.496501  2724 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:59.496901  2502 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:59.496943  2502 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:59.497001  2502 hybrid_clock.cc:648] HybridClock initialized: now 1786515599497001 us; error 0 us; skew 500 ppm
I20260812 06:19:59.497783  2502 webserver.cc:533] Webserver started at http://127.2.113.190:44089/ using document root <none> and password file <none>
I20260812 06:19:59.497917  2502 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:59.497956  2502 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:59.498008  2502 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:59.498346  2502 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/master-0-root/instance:
uuid: "1f38e6dc0d9b4032b559525f7cfb2963"
format_stamp: "Formatted at 2026-08-12 06:19:59 on dist-test-slave-pgkr"
I20260812 06:19:59.499845  2502 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:59.500710  2733 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:59.500936  2502 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:59.500999  2502 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/master-0-root
uuid: "1f38e6dc0d9b4032b559525f7cfb2963"
format_stamp: "Formatted at 2026-08-12 06:19:59 on dist-test-slave-pgkr"
I20260812 06:19:59.501102  2502 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-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:59.506806  2502 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:59.507136  2502 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:59.512003  2502 rpc_server.cc:307] RPC server started. Bound to: 127.2.113.190:35369
I20260812 06:19:59.517974  2793 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.2.113.190:35369 every 8 connection(s)
I20260812 06:19:59.518440  2794 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:59.520215  2794 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1f38e6dc0d9b4032b559525f7cfb2963: Bootstrap starting.
I20260812 06:19:59.520987  2794 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 1f38e6dc0d9b4032b559525f7cfb2963: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:59.522050  2794 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1f38e6dc0d9b4032b559525f7cfb2963: No bootstrap required, opened a new log
I20260812 06:19:59.522504  2794 raft_consensus.cc:359] T 00000000000000000000000000000000 P 1f38e6dc0d9b4032b559525f7cfb2963 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1f38e6dc0d9b4032b559525f7cfb2963" member_type: VOTER }
I20260812 06:19:59.522590  2794 raft_consensus.cc:385] T 00000000000000000000000000000000 P 1f38e6dc0d9b4032b559525f7cfb2963 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:59.522677  2794 raft_consensus.cc:740] T 00000000000000000000000000000000 P 1f38e6dc0d9b4032b559525f7cfb2963 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 1f38e6dc0d9b4032b559525f7cfb2963, State: Initialized, Role: FOLLOWER
I20260812 06:19:59.522943  2794 consensus_queue.cc:260] T 00000000000000000000000000000000 P 1f38e6dc0d9b4032b559525f7cfb2963 [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: "1f38e6dc0d9b4032b559525f7cfb2963" member_type: VOTER }
I20260812 06:19:59.523077  2794 raft_consensus.cc:399] T 00000000000000000000000000000000 P 1f38e6dc0d9b4032b559525f7cfb2963 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:59.523166  2794 raft_consensus.cc:493] T 00000000000000000000000000000000 P 1f38e6dc0d9b4032b559525f7cfb2963 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:59.523241  2794 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 1f38e6dc0d9b4032b559525f7cfb2963 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:59.524108  2794 raft_consensus.cc:515] T 00000000000000000000000000000000 P 1f38e6dc0d9b4032b559525f7cfb2963 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1f38e6dc0d9b4032b559525f7cfb2963" member_type: VOTER }
I20260812 06:19:59.524243  2794 leader_election.cc:304] T 00000000000000000000000000000000 P 1f38e6dc0d9b4032b559525f7cfb2963 [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: 1f38e6dc0d9b4032b559525f7cfb2963; no voters: 
I20260812 06:19:59.524387  2794 leader_election.cc:290] T 00000000000000000000000000000000 P 1f38e6dc0d9b4032b559525f7cfb2963 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:59.524510  2797 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 1f38e6dc0d9b4032b559525f7cfb2963 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:59.524744  2797 raft_consensus.cc:697] T 00000000000000000000000000000000 P 1f38e6dc0d9b4032b559525f7cfb2963 [term 1 LEADER]: Becoming Leader. State: Replica: 1f38e6dc0d9b4032b559525f7cfb2963, State: Running, Role: LEADER
I20260812 06:19:59.524849  2794 sys_catalog.cc:565] T 00000000000000000000000000000000 P 1f38e6dc0d9b4032b559525f7cfb2963 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:59.524910  2797 consensus_queue.cc:237] T 00000000000000000000000000000000 P 1f38e6dc0d9b4032b559525f7cfb2963 [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: "1f38e6dc0d9b4032b559525f7cfb2963" member_type: VOTER }
I20260812 06:19:59.525374  2798 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1f38e6dc0d9b4032b559525f7cfb2963 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "1f38e6dc0d9b4032b559525f7cfb2963" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1f38e6dc0d9b4032b559525f7cfb2963" member_type: VOTER } }
I20260812 06:19:59.525403  2799 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1f38e6dc0d9b4032b559525f7cfb2963 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 1f38e6dc0d9b4032b559525f7cfb2963. Latest consensus state: current_term: 1 leader_uuid: "1f38e6dc0d9b4032b559525f7cfb2963" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1f38e6dc0d9b4032b559525f7cfb2963" member_type: VOTER } }
I20260812 06:19:59.525465  2798 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1f38e6dc0d9b4032b559525f7cfb2963 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:59.525485  2799 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1f38e6dc0d9b4032b559525f7cfb2963 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:59.525718  2802 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:59.526667  2802 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:59.526870  2502 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:59.528524  2802 catalog_manager.cc:1383] Generated new cluster ID: f31459a1e43e4de0a252eace664591b2
I20260812 06:19:59.528589  2802 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:59.535179  2802 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:59.535698  2802 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:59.541368  2802 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 1f38e6dc0d9b4032b559525f7cfb2963: Generated new TSK 0
I20260812 06:19:59.541522  2802 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:59.543025  2502 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:19:59.544906  2502 server_base.cc:1061] running on GCE node
W20260812 06:19:59.544965  2818 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:59.545017  2820 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:59.544903  2817 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:59.545306  2502 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:59.545349  2502 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:59.545364  2502 hybrid_clock.cc:648] HybridClock initialized: now 1786515599545365 us; error 0 us; skew 500 ppm
I20260812 06:19:59.546228  2502 webserver.cc:533] Webserver started at http://127.2.113.129:35417/ using document root <none> and password file <none>
I20260812 06:19:59.546406  2502 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:59.546453  2502 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:59.546559  2502 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:59.546942  2502 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root/instance:
uuid: "6901337897a445a78cb76ae65385421f"
format_stamp: "Formatted at 2026-08-12 06:19:59 on dist-test-slave-pgkr"
I20260812 06:19:59.548318  2502 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:59.549275  2825 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:59.549512  2502 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:59.549599  2502 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root
uuid: "6901337897a445a78cb76ae65385421f"
format_stamp: "Formatted at 2026-08-12 06:19:59 on dist-test-slave-pgkr"
I20260812 06:19:59.549683  2502 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-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:59.561090  2502 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:59.561412  2502 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:59.561708  2502 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:59.562130  2502 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:59.562191  2502 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:59.562248  2502 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:59.562299  2502 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:59.566479  2502 rpc_server.cc:307] RPC server started. Bound to: 127.2.113.129:44505
I20260812 06:19:59.567937  2899 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.2.113.129:44505 every 8 connection(s)
I20260812 06:19:59.572327  2900 heartbeater.cc:344] Connected to a master server at 127.2.113.190:35369
I20260812 06:19:59.572445  2900 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:59.572657  2900 heartbeater.cc:507] Master 127.2.113.190:35369 requested a full tablet report, sending...
I20260812 06:19:59.573344  2754 ts_manager.cc:194] Registered new tserver with Master: 6901337897a445a78cb76ae65385421f (127.2.113.129:44505)
I20260812 06:19:59.574079  2754 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:58274
I20260812 06:19:59.574330  2502 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.006707071s
I20260812 06:19:59.580945  2754 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:58284:
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:59.589624  2860 tablet_service.cc:1511] Processing CreateTablet for tablet 6ffb5d78349f467bb9fe79947ab63bbe (DEFAULT_TABLE table=heavy-update-compaction-test [id=bbfaf0cdb34c46729b55671ba20c7ef4]), partition=
I20260812 06:19:59.589875  2860 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 6ffb5d78349f467bb9fe79947ab63bbe. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:59.591861  2912 tablet_bootstrap.cc:492] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Bootstrap starting.
I20260812 06:19:59.592685  2912 tablet_bootstrap.cc:654] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:59.593679  2912 tablet_bootstrap.cc:492] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: No bootstrap required, opened a new log
I20260812 06:19:59.593758  2912 ts_tablet_manager.cc:1403] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:59.594076  2912 raft_consensus.cc:359] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6901337897a445a78cb76ae65385421f" member_type: VOTER last_known_addr { host: "127.2.113.129" port: 44505 } }
I20260812 06:19:59.594161  2912 raft_consensus.cc:385] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:59.594185  2912 raft_consensus.cc:740] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6901337897a445a78cb76ae65385421f, State: Initialized, Role: FOLLOWER
I20260812 06:19:59.594326  2912 consensus_queue.cc:260] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f [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: "6901337897a445a78cb76ae65385421f" member_type: VOTER last_known_addr { host: "127.2.113.129" port: 44505 } }
I20260812 06:19:59.594412  2912 raft_consensus.cc:399] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:59.594436  2912 raft_consensus.cc:493] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:59.594465  2912 raft_consensus.cc:3060] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:59.595376  2912 raft_consensus.cc:515] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6901337897a445a78cb76ae65385421f" member_type: VOTER last_known_addr { host: "127.2.113.129" port: 44505 } }
I20260812 06:19:59.595515  2912 leader_election.cc:304] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f [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: 6901337897a445a78cb76ae65385421f; no voters: 
I20260812 06:19:59.595678  2912 leader_election.cc:290] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:59.595816  2915 raft_consensus.cc:2804] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:59.595942  2912 ts_tablet_manager.cc:1434] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:59.595983  2900 heartbeater.cc:499] Master 127.2.113.190:35369 was elected leader, sending a full tablet report...
I20260812 06:19:59.596056  2915 raft_consensus.cc:697] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f [term 1 LEADER]: Becoming Leader. State: Replica: 6901337897a445a78cb76ae65385421f, State: Running, Role: LEADER
I20260812 06:19:59.596204  2915 consensus_queue.cc:237] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f [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: "6901337897a445a78cb76ae65385421f" member_type: VOTER last_known_addr { host: "127.2.113.129" port: 44505 } }
I20260812 06:19:59.597476  2754 catalog_manager.cc:5719] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f reported cstate change: term changed from 0 to 1, leader changed from <none> to 6901337897a445a78cb76ae65385421f (127.2.113.129). New cstate: current_term: 1 leader_uuid: "6901337897a445a78cb76ae65385421f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6901337897a445a78cb76ae65385421f" member_type: VOTER last_known_addr { host: "127.2.113.129" port: 44505 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:59.661862  2502 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.021s	sys 0.004s
I20260812 06:19:59.818276  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushMRSOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=19.054940
I20260812 06:19:59.969377  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushMRSOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.151s	user 0.106s	sys 0.043s Metrics: {"bytes_written":12840811,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":212,"dirs.run_wall_time_us":971,"drs_written":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41042,"lbm_writes_lt_1ms":780,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":84608,"update_count":1565}
I20260812 06:19:59.970175  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=2.188937
I20260812 06:19:59.997145  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.027s	user 0.010s	sys 0.003s Metrics: {"bytes_written":3282159,"delete_count":0,"lbm_write_time_us":5608,"lbm_writes_lt_1ms":83,"reinsert_count":0,"update_count":400}
I20260812 06:19:59.997623  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling LogGCOp(6ffb5d78349f467bb9fe79947ab63bbe): free 20743831 bytes of WAL
I20260812 06:19:59.997828  2831 log_reader.cc:385] T 6ffb5d78349f467bb9fe79947ab63bbe: removed 2 log segments from log reader
I20260812 06:19:59.997891  2831 log.cc:1079] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/6ffb5d78349f467bb9fe79947ab63bbe/wal-000000001 (ops 1-6)
I20260812 06:19:59.997941  2831 log.cc:1079] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/6ffb5d78349f467bb9fe79947ab63bbe/wal-000000002 (ops 7-11)
I20260812 06:20:00.002489  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: LogGCOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.005s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:20:00.002851  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling UndoDeltaBlockGCOp(6ffb5d78349f467bb9fe79947ab63bbe): 16821649 bytes on disk
I20260812 06:20:00.003263  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: UndoDeltaBlockGCOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:20:00.003684  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=2.188937
I20260812 06:20:00.015654  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3979584,"delete_count":0,"lbm_write_time_us":4401,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:20:00.016217  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling MajorDeltaCompactionOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=1.000000
I20260812 06:20:00.197952  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: MajorDeltaCompactionOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.182s	user 0.105s	sys 0.075s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24405549,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":492,"lbm_read_time_us":13999,"lbm_reads_lt_1ms":559,"lbm_write_time_us":28988,"lbm_writes_lt_1ms":533,"mutex_wait_us":33,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":15104,"thread_start_us":324,"threads_started":5,"update_count":2450}
I20260812 06:20:00.198941  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=14.095187
I20260812 06:20:00.250097  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.051s	user 0.030s	sys 0.018s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22832,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:00.250883  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=2.188937
I20260812 06:20:00.262814  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4248,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:00.263285  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling MajorDeltaCompactionOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=1.000000
I20260812 06:20:00.434551  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: MajorDeltaCompactionOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.171s	user 0.116s	sys 0.053s 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":2115,"lbm_read_time_us":13549,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27526,"lbm_writes_lt_1ms":543,"mutex_wait_us":33,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13952,"update_count":2500}
I20260812 06:20:00.435310  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=14.095187
I20260812 06:20:00.494105  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.059s	user 0.027s	sys 0.026s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20321,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:00.494750  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=2.188937
I20260812 06:20:00.505331  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4182,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:00.506439  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling MajorDeltaCompactionOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=1.000000
I20260812 06:20:00.675228  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: MajorDeltaCompactionOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.169s	user 0.114s	sys 0.053s 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":190,"lbm_read_time_us":13354,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26529,"lbm_writes_lt_1ms":543,"mutex_wait_us":49,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2500}
I20260812 06:20:00.675868  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=11.118625
I20260812 06:20:00.712357  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.036s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15456,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:00.713068  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=2.188937
I20260812 06:20:00.730021  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.017s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5118,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:00.730542  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling MajorDeltaCompactionOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=1.000000
I20260812 06:20:00.898725  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: MajorDeltaCompactionOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.168s	user 0.108s	sys 0.053s 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":688,"lbm_read_time_us":9851,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26919,"lbm_writes_lt_1ms":443,"mutex_wait_us":83,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13056,"update_count":2000}
I20260812 06:20:00.899474  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=14.095187
I20260812 06:20:00.954515  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.055s	user 0.042s	sys 0.004s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22609,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:00.955077  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=2.188937
I20260812 06:20:00.967199  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4333,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:00.967902  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling MajorDeltaCompactionOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=1.000000
I20260812 06:20:01.119203  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: MajorDeltaCompactionOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.151s	user 0.097s	sys 0.046s 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":1224,"lbm_read_time_us":9874,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29753,"lbm_writes_lt_1ms":543,"mutex_wait_us":344,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2500}
I20260812 06:20:01.119952  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=14.095187
I20260812 06:20:01.167464  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.047s	user 0.016s	sys 0.025s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18249,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:01.167987  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=2.188937
I20260812 06:20:01.179874  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.012s	user 0.001s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4237,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:01.180356  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushMRSOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=1.000000
I20260812 06:20:01.211099  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushMRSOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.031s	user 0.029s	sys 0.001s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":237,"dirs.run_wall_time_us":1241,"drs_written":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1718,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:01.211666  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling LogGCOp(6ffb5d78349f467bb9fe79947ab63bbe): free 112239326 bytes of WAL
I20260812 06:20:01.211884  2831 log_reader.cc:385] T 6ffb5d78349f467bb9fe79947ab63bbe: removed 11 log segments from log reader
I20260812 06:20:01.211941  2831 log.cc:1079] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/6ffb5d78349f467bb9fe79947ab63bbe/wal-000000003 (ops 12-16)
I20260812 06:20:01.211994  2831 log.cc:1079] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/6ffb5d78349f467bb9fe79947ab63bbe/wal-000000004 (ops 17-21)
I20260812 06:20:01.212046  2831 log.cc:1079] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/6ffb5d78349f467bb9fe79947ab63bbe/wal-000000005 (ops 22-26)
I20260812 06:20:01.212086  2831 log.cc:1079] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/6ffb5d78349f467bb9fe79947ab63bbe/wal-000000006 (ops 27-30)
I20260812 06:20:01.212118  2831 log.cc:1079] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/6ffb5d78349f467bb9fe79947ab63bbe/wal-000000007 (ops 31-35)
I20260812 06:20:01.212160  2831 log.cc:1079] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/6ffb5d78349f467bb9fe79947ab63bbe/wal-000000008 (ops 36-40)
I20260812 06:20:01.212199  2831 log.cc:1079] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/6ffb5d78349f467bb9fe79947ab63bbe/wal-000000009 (ops 41-45)
I20260812 06:20:01.212255  2831 log.cc:1079] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/6ffb5d78349f467bb9fe79947ab63bbe/wal-000000010 (ops 46-50)
I20260812 06:20:01.212292  2831 log.cc:1079] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/6ffb5d78349f467bb9fe79947ab63bbe/wal-000000011 (ops 51-55)
I20260812 06:20:01.212328  2831 log.cc:1079] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/6ffb5d78349f467bb9fe79947ab63bbe/wal-000000012 (ops 56-60)
I20260812 06:20:01.212364  2831 log.cc:1079] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/6ffb5d78349f467bb9fe79947ab63bbe/wal-000000013 (ops 61-65)
I20260812 06:20:01.237653  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: LogGCOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.026s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:20:01.238075  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling UndoDeltaBlockGCOp(6ffb5d78349f467bb9fe79947ab63bbe): 447 bytes on disk
I20260812 06:20:01.238485  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: UndoDeltaBlockGCOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:20:01.239078  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=3.181125
I20260812 06:20:01.254945  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.016s	user 0.009s	sys 0.007s Metrics: {"bytes_written":5128263,"delete_count":0,"lbm_write_time_us":6520,"lbm_writes_lt_1ms":128,"reinsert_count":0,"update_count":625}
I20260812 06:20:01.255398  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling LogGCOp(6ffb5d78349f467bb9fe79947ab63bbe): free 12017983 bytes of WAL
I20260812 06:20:01.255614  2831 log_reader.cc:385] T 6ffb5d78349f467bb9fe79947ab63bbe: removed 1 log segments from log reader
I20260812 06:20:01.255673  2831 log.cc:1079] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/6ffb5d78349f467bb9fe79947ab63bbe/wal-000000014 (ops 66-70)
I20260812 06:20:01.257984  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: LogGCOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:20:01.258294  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=1.196750
I20260812 06:20:01.272810  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.014s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3077030,"delete_count":0,"lbm_write_time_us":4226,"lbm_writes_lt_1ms":78,"reinsert_count":0,"update_count":375}
I20260812 06:20:01.273422  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling MajorDeltaCompactionOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=1.000000
I20260812 06:20:01.479676  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: MajorDeltaCompactionOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.206s	user 0.162s	sys 0.042s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020722,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":494,"lbm_read_time_us":15709,"lbm_reads_lt_1ms":770,"lbm_write_time_us":40663,"lbm_writes_lt_1ms":743,"mutex_wait_us":39,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":11904,"thread_start_us":84,"threads_started":1,"update_count":3500}
I20260812 06:20:01.480827  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=15.087375
I20260812 06:20:01.526700  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.046s	user 0.035s	sys 0.008s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":18208,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:20:01.527391  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=2.188937
I20260812 06:20:01.549818  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.022s	user 0.001s	sys 0.012s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":6023,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:01.550362  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=2.188937
I20260812 06:20:01.560658  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3631,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:01.561316  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling MajorDeltaCompactionOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=1.000000
I20260812 06:20:01.731003  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: MajorDeltaCompactionOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.169s	user 0.130s	sys 0.039s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918203,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":107,"lbm_read_time_us":11967,"lbm_reads_lt_1ms":673,"lbm_write_time_us":32525,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":3000}
I20260812 06:20:01.731642  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=14.095187
I20260812 06:20:01.790066  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.058s	user 0.030s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":27238,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:01.790541  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=2.188937
I20260812 06:20:01.812690  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.022s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4447,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:01.813228  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=2.188937
I20260812 06:20:01.828054  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.015s	user 0.004s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5728,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:01.828656  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling MajorDeltaCompactionOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=1.000000
I20260812 06:20:02.002385  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: MajorDeltaCompactionOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.174s	user 0.132s	sys 0.039s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918215,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":189,"lbm_read_time_us":13911,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33940,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:20:02.002970  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=14.095187
I20260812 06:20:02.065279  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.062s	user 0.019s	sys 0.041s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":27850,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:20:02.065861  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=2.188937
I20260812 06:20:02.079123  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.013s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4772,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:02.079643  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling MajorDeltaCompactionOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=1.000000
I20260812 06:20:02.238324  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: MajorDeltaCompactionOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.158s	user 0.116s	sys 0.025s 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":1028,"lbm_read_time_us":10003,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29593,"lbm_writes_lt_1ms":543,"mutex_wait_us":273,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:20:02.238991  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=14.095187
I20260812 06:20:02.296880  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.058s	user 0.016s	sys 0.031s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22101,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:02.297505  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=2.188937
I20260812 06:20:02.308374  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4089,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:02.309093  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling MajorDeltaCompactionOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=1.000000
I20260812 06:20:02.502260  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: MajorDeltaCompactionOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.193s	user 0.128s	sys 0.056s 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":804,"lbm_read_time_us":14279,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30781,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14336,"update_count":2500}
I20260812 06:20:02.503098  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=14.095187
I20260812 06:20:02.555248  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.052s	user 0.023s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21564,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:02.555749  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushMRSOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=1.000000
I20260812 06:20:02.596619  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushMRSOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.041s	user 0.025s	sys 0.001s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":220,"dirs.run_wall_time_us":1817,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2003,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:02.597259  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=3.181125
I20260812 06:20:02.612391  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.015s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4527,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:02.612923  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling LogGCOp(6ffb5d78349f467bb9fe79947ab63bbe): free 112239324 bytes of WAL
I20260812 06:20:02.613175  2831 log_reader.cc:385] T 6ffb5d78349f467bb9fe79947ab63bbe: removed 11 log segments from log reader
I20260812 06:20:02.613222  2831 log.cc:1079] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/6ffb5d78349f467bb9fe79947ab63bbe/wal-000000015 (ops 71-75)
I20260812 06:20:02.613250  2831 log.cc:1079] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/6ffb5d78349f467bb9fe79947ab63bbe/wal-000000016 (ops 76-80)
I20260812 06:20:02.613312  2831 log.cc:1079] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/6ffb5d78349f467bb9fe79947ab63bbe/wal-000000017 (ops 81-85)
I20260812 06:20:02.613379  2831 log.cc:1079] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/6ffb5d78349f467bb9fe79947ab63bbe/wal-000000018 (ops 86-90)
I20260812 06:20:02.613426  2831 log.cc:1079] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/6ffb5d78349f467bb9fe79947ab63bbe/wal-000000019 (ops 91-95)
I20260812 06:20:02.613466  2831 log.cc:1079] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/6ffb5d78349f467bb9fe79947ab63bbe/wal-000000020 (ops 96-100)
I20260812 06:20:02.613540  2831 log.cc:1079] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/6ffb5d78349f467bb9fe79947ab63bbe/wal-000000021 (ops 101-105)
I20260812 06:20:02.613582  2831 log.cc:1079] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/6ffb5d78349f467bb9fe79947ab63bbe/wal-000000022 (ops 106-110)
I20260812 06:20:02.613610  2831 log.cc:1079] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/6ffb5d78349f467bb9fe79947ab63bbe/wal-000000023 (ops 111-114)
I20260812 06:20:02.613648  2831 log.cc:1079] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/6ffb5d78349f467bb9fe79947ab63bbe/wal-000000024 (ops 115-119)
I20260812 06:20:02.613687  2831 log.cc:1079] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/6ffb5d78349f467bb9fe79947ab63bbe/wal-000000025 (ops 120-124)
I20260812 06:20:02.638162  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: LogGCOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.025s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:20:02.638741  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=2.188937
I20260812 06:20:02.655613  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.017s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4212,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:02.656055  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=2.188937
I20260812 06:20:02.666631  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4133,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:02.667119  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling MajorDeltaCompactionOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=1.000000
I20260812 06:20:02.894164  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: MajorDeltaCompactionOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.227s	user 0.147s	sys 0.072s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020734,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":422,"lbm_read_time_us":16450,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40471,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":9984,"thread_start_us":75,"threads_started":1,"update_count":3500}
I20260812 06:20:02.894960  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling UndoDeltaBlockGCOp(6ffb5d78349f467bb9fe79947ab63bbe): 462 bytes on disk
I20260812 06:20:02.895793  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: UndoDeltaBlockGCOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":96,"lbm_reads_lt_1ms":4}
I20260812 06:20:02.896790  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=18.063937
I20260812 06:20:02.961349  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.064s	user 0.038s	sys 0.024s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":29457,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:02.961899  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=2.188937
I20260812 06:20:02.975203  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4774,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:02.975749  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling MajorDeltaCompactionOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=1.000000
I20260812 06:20:03.144964  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: MajorDeltaCompactionOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.169s	user 0.138s	sys 0.030s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918099,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":592,"lbm_read_time_us":13569,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34848,"lbm_writes_lt_1ms":643,"mutex_wait_us":279,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":17792,"update_count":3000}
I20260812 06:20:03.145612  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=14.095187
I20260812 06:20:03.207060  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.061s	user 0.032s	sys 0.028s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":27883,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:20:03.207672  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=2.188937
I20260812 06:20:03.231922  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.024s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4460,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.232450  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=2.188937
I20260812 06:20:03.244217  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.012s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4323,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.245095  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling MajorDeltaCompactionOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=1.000000
I20260812 06:20:03.426393  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: MajorDeltaCompactionOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.181s	user 0.141s	sys 0.040s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918217,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":256,"lbm_read_time_us":13267,"lbm_reads_lt_1ms":673,"lbm_write_time_us":40878,"lbm_writes_lt_1ms":643,"mutex_wait_us":23,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":22400,"update_count":3000}
I20260812 06:20:03.427114  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=14.095187
I20260812 06:20:03.477451  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.050s	user 0.031s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19682,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:03.478016  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=2.188937
I20260812 06:20:03.494067  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5923,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.494829  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling MajorDeltaCompactionOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=1.000000
I20260812 06:20:03.656456  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: MajorDeltaCompactionOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.161s	user 0.114s	sys 0.044s 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":1400,"lbm_read_time_us":10809,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32001,"lbm_writes_lt_1ms":543,"mutex_wait_us":67,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2500}
I20260812 06:20:03.657256  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=12.110812
I20260812 06:20:03.708707  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.051s	user 0.025s	sys 0.024s Metrics: {"bytes_written":13620267,"delete_count":0,"lbm_write_time_us":23132,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":334,"reinsert_count":0,"update_count":1660}
I20260812 06:20:03.709498  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=1.196750
I20260812 06:20:03.731659  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.022s	user 0.008s	sys 0.000s Metrics: {"bytes_written":2789855,"delete_count":0,"lbm_write_time_us":3111,"lbm_writes_lt_1ms":71,"reinsert_count":0,"update_count":340}
I20260812 06:20:03.732183  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=2.188937
I20260812 06:20:03.743544  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.011s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4180,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.744063  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling MajorDeltaCompactionOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=1.000000
I20260812 06:20:03.926023  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: MajorDeltaCompactionOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.182s	user 0.115s	sys 0.060s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815776,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":167,"lbm_read_time_us":13164,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31247,"lbm_writes_lt_1ms":543,"mutex_wait_us":45,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2500}
I20260812 06:20:03.926818  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=14.095187
I20260812 06:20:03.994875  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.068s	user 0.033s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23961,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:03.995467  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=2.188937
I20260812 06:20:04.008379  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.013s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4839,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:04.009367  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushMRSOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=1.000000
I20260812 06:20:04.042274  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushMRSOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.033s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":183,"dirs.run_wall_time_us":1192,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1632,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:04.042999  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling LogGCOp(6ffb5d78349f467bb9fe79947ab63bbe): free 124710551 bytes of WAL
I20260812 06:20:04.043229  2831 log_reader.cc:385] T 6ffb5d78349f467bb9fe79947ab63bbe: removed 12 log segments from log reader
I20260812 06:20:04.043273  2831 log.cc:1079] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/6ffb5d78349f467bb9fe79947ab63bbe/wal-000000026 (ops 125-129)
I20260812 06:20:04.043303  2831 log.cc:1079] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/6ffb5d78349f467bb9fe79947ab63bbe/wal-000000027 (ops 130-134)
I20260812 06:20:04.043366  2831 log.cc:1079] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/6ffb5d78349f467bb9fe79947ab63bbe/wal-000000028 (ops 135-139)
I20260812 06:20:04.043411  2831 log.cc:1079] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/6ffb5d78349f467bb9fe79947ab63bbe/wal-000000029 (ops 140-144)
I20260812 06:20:04.043455  2831 log.cc:1079] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/6ffb5d78349f467bb9fe79947ab63bbe/wal-000000030 (ops 145-149)
I20260812 06:20:04.043524  2831 log.cc:1079] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/6ffb5d78349f467bb9fe79947ab63bbe/wal-000000031 (ops 150-154)
I20260812 06:20:04.043560  2831 log.cc:1079] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/6ffb5d78349f467bb9fe79947ab63bbe/wal-000000032 (ops 155-159)
I20260812 06:20:04.043599  2831 log.cc:1079] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/6ffb5d78349f467bb9fe79947ab63bbe/wal-000000033 (ops 160-164)
I20260812 06:20:04.043637  2831 log.cc:1079] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/6ffb5d78349f467bb9fe79947ab63bbe/wal-000000034 (ops 165-169)
I20260812 06:20:04.043679  2831 log.cc:1079] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/6ffb5d78349f467bb9fe79947ab63bbe/wal-000000035 (ops 170-174)
I20260812 06:20:04.043738  2831 log.cc:1079] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/6ffb5d78349f467bb9fe79947ab63bbe/wal-000000036 (ops 175-179)
I20260812 06:20:04.043778  2831 log.cc:1079] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: Deleting log segment in path: /tmp/dist-test-taskzwOGrS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515593773032-2502-0/minicluster-data/ts-0-root/wals/6ffb5d78349f467bb9fe79947ab63bbe/wal-000000037 (ops 180-184)
I20260812 06:20:04.072425  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: LogGCOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.029s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:20:04.072885  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=3.181125
I20260812 06:20:04.093778  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.021s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7328,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:04.094215  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=2.188937
I20260812 06:20:04.103838  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3608,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:04.104305  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling UndoDeltaBlockGCOp(6ffb5d78349f467bb9fe79947ab63bbe): 462 bytes on disk
I20260812 06:20:04.104732  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: UndoDeltaBlockGCOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:20:04.105247  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling MajorDeltaCompactionOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=1.000000
I20260812 06:20:04.331616  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: MajorDeltaCompactionOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.226s	user 0.155s	sys 0.059s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020732,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":471,"lbm_read_time_us":17063,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39762,"lbm_writes_lt_1ms":743,"mutex_wait_us":42,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":14720,"thread_start_us":82,"threads_started":1,"update_count":3500}
I20260812 06:20:04.332388  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=18.063937
I20260812 06:20:04.389247  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.057s	user 0.038s	sys 0.016s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":25472,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:04.389768  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=2.188937
I20260812 06:20:04.400493  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: FlushDeltaMemStoresOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4265,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:04.401124  2901 maintenance_manager.cc:419] P 6901337897a445a78cb76ae65385421f: Scheduling MajorDeltaCompactionOp(6ffb5d78349f467bb9fe79947ab63bbe): perf score=1.000000
I20260812 06:20:04.426438  2502 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.764s	user 1.755s	sys 0.154s
I20260812 06:20:04.504972  2502 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.078s	user 0.001s	sys 0.000s
I20260812 06:20:04.505510  2502 tablet_server.cc:179] TabletServer@127.2.113.129:0 shutting down...
I20260812 06:20:04.570817  2831 maintenance_manager.cc:643] P 6901337897a445a78cb76ae65385421f: MajorDeltaCompactionOp(6ffb5d78349f467bb9fe79947ab63bbe) complete. Timing: real 0.169s	user 0.135s	sys 0.034s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918097,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":936,"lbm_read_time_us":11879,"lbm_reads_lt_1ms":668,"lbm_write_time_us":34364,"lbm_writes_lt_1ms":643,"mutex_wait_us":373,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":3000}
I20260812 06:20:04.571580  2502 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:04.571813  2502 tablet_replica.cc:333] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f: stopping tablet replica
I20260812 06:20:04.571950  2502 raft_consensus.cc:2243] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:04.572150  2502 raft_consensus.cc:2272] T 6ffb5d78349f467bb9fe79947ab63bbe P 6901337897a445a78cb76ae65385421f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:04.577003  2502 tablet_server.cc:196] TabletServer@127.2.113.129:0 shutdown complete.
I20260812 06:20:04.625113  2502 master.cc:562] Master@127.2.113.190:35369 shutting down...
I20260812 06:20:04.628239  2502 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 1f38e6dc0d9b4032b559525f7cfb2963 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:04.628396  2502 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 1f38e6dc0d9b4032b559525f7cfb2963 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:04.628445  2502 tablet_replica.cc:333] T 00000000000000000000000000000000 P 1f38e6dc0d9b4032b559525f7cfb2963: stopping tablet replica
I20260812 06:20:04.640805  2502 master.cc:584] Master@127.2.113.190:35369 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5248 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10947 ms total)

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