[==========] 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:20:22.351130  2241 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.2.48.126:34399
I20260812 06:20:22.352612  2241 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:20:22.353626  2241 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:22.362267  2249 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:20:22.362308  2250 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:20:22.362442  2241 server_base.cc:1061] running on GCE node
W20260812 06:20:22.362588  2253 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:20:22.363195  2241 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:22.363314  2241 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:20:22.363358  2241 hybrid_clock.cc:648] HybridClock initialized: now 1786515622363355 us; error 0 us; skew 500 ppm
I20260812 06:20:22.365417  2241 webserver.cc:533] Webserver started at http://127.2.48.126:40323/ using document root <none> and password file <none>
I20260812 06:20:22.366083  2241 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:22.366156  2241 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:22.366395  2241 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:22.368137  2241 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/master-0-root/instance:
uuid: "0d29a8c2ed594593bce840c3255edfb8"
format_stamp: "Formatted at 2026-08-12 06:20:22 on dist-test-slave-t7g5"
I20260812 06:20:22.372660  2241 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.003s	sys 0.003s
I20260812 06:20:22.375746  2266 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:20:22.377138  2241 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:20:22.377287  2241 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/master-0-root
uuid: "0d29a8c2ed594593bce840c3255edfb8"
format_stamp: "Formatted at 2026-08-12 06:20:22 on dist-test-slave-t7g5"
I20260812 06:20:22.377425  2241 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-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:20:22.398645  2241 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:22.399380  2241 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:20:22.399559  2241 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:22.407938  2241 rpc_server.cc:307] RPC server started. Bound to: 127.2.48.126:34399
I20260812 06:20:22.407943  2351 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.2.48.126:34399 every 8 connection(s)
I20260812 06:20:22.410408  2352 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:20:22.416225  2352 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0d29a8c2ed594593bce840c3255edfb8: Bootstrap starting.
I20260812 06:20:22.418766  2352 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 0d29a8c2ed594593bce840c3255edfb8: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:22.419745  2352 log.cc:826] T 00000000000000000000000000000000 P 0d29a8c2ed594593bce840c3255edfb8: Log is configured to *not* fsync() on all Append() calls
I20260812 06:20:22.421756  2352 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0d29a8c2ed594593bce840c3255edfb8: No bootstrap required, opened a new log
I20260812 06:20:22.424677  2352 raft_consensus.cc:359] T 00000000000000000000000000000000 P 0d29a8c2ed594593bce840c3255edfb8 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0d29a8c2ed594593bce840c3255edfb8" member_type: VOTER }
I20260812 06:20:22.424861  2352 raft_consensus.cc:385] T 00000000000000000000000000000000 P 0d29a8c2ed594593bce840c3255edfb8 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:22.424902  2352 raft_consensus.cc:740] T 00000000000000000000000000000000 P 0d29a8c2ed594593bce840c3255edfb8 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0d29a8c2ed594593bce840c3255edfb8, State: Initialized, Role: FOLLOWER
I20260812 06:20:22.425567  2352 consensus_queue.cc:260] T 00000000000000000000000000000000 P 0d29a8c2ed594593bce840c3255edfb8 [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: "0d29a8c2ed594593bce840c3255edfb8" member_type: VOTER }
I20260812 06:20:22.425751  2352 raft_consensus.cc:399] T 00000000000000000000000000000000 P 0d29a8c2ed594593bce840c3255edfb8 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:22.425824  2352 raft_consensus.cc:493] T 00000000000000000000000000000000 P 0d29a8c2ed594593bce840c3255edfb8 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:22.425920  2352 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 0d29a8c2ed594593bce840c3255edfb8 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:22.426811  2352 raft_consensus.cc:515] T 00000000000000000000000000000000 P 0d29a8c2ed594593bce840c3255edfb8 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0d29a8c2ed594593bce840c3255edfb8" member_type: VOTER }
I20260812 06:20:22.427258  2352 leader_election.cc:304] T 00000000000000000000000000000000 P 0d29a8c2ed594593bce840c3255edfb8 [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: 0d29a8c2ed594593bce840c3255edfb8; no voters: 
I20260812 06:20:22.427598  2352 leader_election.cc:290] T 00000000000000000000000000000000 P 0d29a8c2ed594593bce840c3255edfb8 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:22.427767  2355 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 0d29a8c2ed594593bce840c3255edfb8 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:22.428027  2355 raft_consensus.cc:697] T 00000000000000000000000000000000 P 0d29a8c2ed594593bce840c3255edfb8 [term 1 LEADER]: Becoming Leader. State: Replica: 0d29a8c2ed594593bce840c3255edfb8, State: Running, Role: LEADER
I20260812 06:20:22.428402  2355 consensus_queue.cc:237] T 00000000000000000000000000000000 P 0d29a8c2ed594593bce840c3255edfb8 [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: "0d29a8c2ed594593bce840c3255edfb8" member_type: VOTER }
I20260812 06:20:22.428607  2352 sys_catalog.cc:565] T 00000000000000000000000000000000 P 0d29a8c2ed594593bce840c3255edfb8 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:22.430258  2357 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0d29a8c2ed594593bce840c3255edfb8 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "0d29a8c2ed594593bce840c3255edfb8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0d29a8c2ed594593bce840c3255edfb8" member_type: VOTER } }
I20260812 06:20:22.430294  2363 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0d29a8c2ed594593bce840c3255edfb8 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 0d29a8c2ed594593bce840c3255edfb8. Latest consensus state: current_term: 1 leader_uuid: "0d29a8c2ed594593bce840c3255edfb8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0d29a8c2ed594593bce840c3255edfb8" member_type: VOTER } }
I20260812 06:20:22.430409  2357 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0d29a8c2ed594593bce840c3255edfb8 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:22.430415  2363 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0d29a8c2ed594593bce840c3255edfb8 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:22.430763  2383 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:22.430848  2241 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:22.433959  2383 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:22.441322  2383 catalog_manager.cc:1383] Generated new cluster ID: 36fa9347aa5c4e27bbdc4038167ee084
I20260812 06:20:22.441438  2383 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:22.458117  2383 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:22.459193  2383 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:22.475770  2383 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 0d29a8c2ed594593bce840c3255edfb8: Generated new TSK 0
I20260812 06:20:22.476604  2383 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:22.496285  2241 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:22.499166  2394 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:20:22.499271  2397 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:20:22.499432  2241 server_base.cc:1061] running on GCE node
W20260812 06:20:22.499307  2393 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:20:22.499923  2241 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:22.500002  2241 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:20:22.500033  2241 hybrid_clock.cc:648] HybridClock initialized: now 1786515622500033 us; error 0 us; skew 500 ppm
I20260812 06:20:22.501055  2241 webserver.cc:533] Webserver started at http://127.2.48.65:44219/ using document root <none> and password file <none>
I20260812 06:20:22.501230  2241 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:22.501284  2241 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:22.501362  2241 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:22.501783  2241 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/ts-0-root/instance:
uuid: "bbabfde0b3c64c2494b4e9d8875fb432"
format_stamp: "Formatted at 2026-08-12 06:20:22 on dist-test-slave-t7g5"
I20260812 06:20:22.503321  2241 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:20:22.504508  2408 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:20:22.504772  2241 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:20:22.504859  2241 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/ts-0-root
uuid: "bbabfde0b3c64c2494b4e9d8875fb432"
format_stamp: "Formatted at 2026-08-12 06:20:22 on dist-test-slave-t7g5"
I20260812 06:20:22.504936  2241 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-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:20:22.514293  2241 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:22.514930  2241 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:22.515807  2241 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:22.516832  2241 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:22.516888  2241 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:22.516945  2241 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:22.516975  2241 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:22.524554  2241 rpc_server.cc:307] RPC server started. Bound to: 127.2.48.65:42147
I20260812 06:20:22.524783  2516 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.2.48.65:42147 every 8 connection(s)
I20260812 06:20:22.540028  2517 heartbeater.cc:344] Connected to a master server at 127.2.48.126:34399
I20260812 06:20:22.540422  2517 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:22.541098  2517 heartbeater.cc:507] Master 127.2.48.126:34399 requested a full tablet report, sending...
I20260812 06:20:22.542884  2294 ts_manager.cc:194] Registered new tserver with Master: bbabfde0b3c64c2494b4e9d8875fb432 (127.2.48.65:42147)
I20260812 06:20:22.542938  2241 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.017594861s
I20260812 06:20:22.544426  2294 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:46030
I20260812 06:20:22.553458  2294 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:46044:
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:20:22.569434  2456 tablet_service.cc:1511] Processing CreateTablet for tablet 945f62e34a934e53a09c250c63b4689e (DEFAULT_TABLE table=heavy-update-compaction-test [id=e1a5904eab794af485ed90e01f575f12]), partition=
I20260812 06:20:22.569994  2456 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 945f62e34a934e53a09c250c63b4689e. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:22.572978  2537 tablet_bootstrap.cc:492] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: Bootstrap starting.
I20260812 06:20:22.573990  2537 tablet_bootstrap.cc:654] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:22.575184  2537 tablet_bootstrap.cc:492] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: No bootstrap required, opened a new log
I20260812 06:20:22.575297  2537 ts_tablet_manager.cc:1403] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:22.576043  2537 raft_consensus.cc:359] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bbabfde0b3c64c2494b4e9d8875fb432" member_type: VOTER last_known_addr { host: "127.2.48.65" port: 42147 } }
I20260812 06:20:22.576169  2537 raft_consensus.cc:385] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:22.576246  2537 raft_consensus.cc:740] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: bbabfde0b3c64c2494b4e9d8875fb432, State: Initialized, Role: FOLLOWER
I20260812 06:20:22.576433  2537 consensus_queue.cc:260] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432 [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: "bbabfde0b3c64c2494b4e9d8875fb432" member_type: VOTER last_known_addr { host: "127.2.48.65" port: 42147 } }
I20260812 06:20:22.576575  2537 raft_consensus.cc:399] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:22.576625  2537 raft_consensus.cc:493] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:22.576675  2537 raft_consensus.cc:3060] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:22.577467  2537 raft_consensus.cc:515] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bbabfde0b3c64c2494b4e9d8875fb432" member_type: VOTER last_known_addr { host: "127.2.48.65" port: 42147 } }
I20260812 06:20:22.577601  2537 leader_election.cc:304] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432 [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: bbabfde0b3c64c2494b4e9d8875fb432; no voters: 
I20260812 06:20:22.577826  2537 leader_election.cc:290] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:22.577940  2543 raft_consensus.cc:2804] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:22.578155  2537 ts_tablet_manager.cc:1434] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: Time spent starting tablet: real 0.003s	user 0.002s	sys 0.001s
I20260812 06:20:22.578176  2543 raft_consensus.cc:697] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432 [term 1 LEADER]: Becoming Leader. State: Replica: bbabfde0b3c64c2494b4e9d8875fb432, State: Running, Role: LEADER
I20260812 06:20:22.578357  2543 consensus_queue.cc:237] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432 [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: "bbabfde0b3c64c2494b4e9d8875fb432" member_type: VOTER last_known_addr { host: "127.2.48.65" port: 42147 } }
I20260812 06:20:22.578416  2517 heartbeater.cc:499] Master 127.2.48.126:34399 was elected leader, sending a full tablet report...
I20260812 06:20:22.581099  2294 catalog_manager.cc:5719] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432 reported cstate change: term changed from 0 to 1, leader changed from <none> to bbabfde0b3c64c2494b4e9d8875fb432 (127.2.48.65). New cstate: current_term: 1 leader_uuid: "bbabfde0b3c64c2494b4e9d8875fb432" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bbabfde0b3c64c2494b4e9d8875fb432" member_type: VOTER last_known_addr { host: "127.2.48.65" port: 42147 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:22.653904  2241 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.064s	user 0.011s	sys 0.020s
I20260812 06:20:22.776183  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushMRSOp(945f62e34a934e53a09c250c63b4689e): perf score=15.086190
I20260812 06:20:22.952065  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushMRSOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.175s	user 0.136s	sys 0.035s Metrics: {"bytes_written":12717735,"cfile_init":1,"compiler_manager_pool.queue_time_us":528,"delete_count":0,"dirs.queue_time_us":360,"dirs.run_cpu_time_us":267,"dirs.run_wall_time_us":1488,"drs_written":1,"lbm_read_time_us":83,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43177,"lbm_writes_lt_1ms":667,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":323456,"thread_start_us":136,"threads_started":1,"update_count":1550}
I20260812 06:20:22.953408  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling LogGCOp(945f62e34a934e53a09c250c63b4689e): free 8725963 bytes of WAL
I20260812 06:20:22.953862  2414 log_reader.cc:385] T 945f62e34a934e53a09c250c63b4689e: removed 1 log segments from log reader
I20260812 06:20:22.953992  2414 log.cc:1079] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/945f62e34a934e53a09c250c63b4689e/wal-000000001 (ops 1-6)
I20260812 06:20:22.956714  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: LogGCOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:20:22.957412  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=2.188937
I20260812 06:20:22.983971  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.026s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5870,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:22.984608  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling UndoDeltaBlockGCOp(945f62e34a934e53a09c250c63b4689e): 12308959 bytes on disk
I20260812 06:20:22.985360  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: UndoDeltaBlockGCOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4}
I20260812 06:20:22.985888  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=2.188937
I20260812 06:20:22.997743  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3885,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:22.998383  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e): perf score=1.000000
I20260812 06:20:23.176616  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.178s	user 0.125s	sys 0.048s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733834,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":709,"lbm_read_time_us":14807,"lbm_reads_lt_1ms":569,"lbm_write_time_us":29239,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5760,"thread_start_us":325,"threads_started":5,"update_count":2500}
I20260812 06:20:23.177237  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=10.126437
I20260812 06:20:23.238790  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.061s	user 0.018s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20364,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:23.239491  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=2.188937
I20260812 06:20:23.256067  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6059,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.256608  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e): perf score=1.000000
I20260812 06:20:23.387081  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.130s	user 0.102s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":380,"lbm_read_time_us":8823,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23248,"lbm_writes_lt_1ms":443,"mutex_wait_us":66,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":39296,"update_count":2000}
I20260812 06:20:23.387969  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=10.126437
I20260812 06:20:23.424351  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.036s	user 0.024s	sys 0.009s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15631,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":1500}
I20260812 06:20:23.424943  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=2.188937
I20260812 06:20:23.438058  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.013s	user 0.005s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4352,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.438529  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e): perf score=1.000000
I20260812 06:20:23.564826  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.126s	user 0.088s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":329,"lbm_read_time_us":8675,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25280,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:20:23.565577  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=10.126437
I20260812 06:20:23.626816  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.061s	user 0.040s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17193,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:23.627604  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=2.188937
I20260812 06:20:23.639587  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4766,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.640151  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e): perf score=1.000000
I20260812 06:20:23.800863  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.161s	user 0.106s	sys 0.045s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1066,"lbm_read_time_us":13052,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23497,"lbm_writes_lt_1ms":443,"mutex_wait_us":340,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9216,"update_count":2000}
I20260812 06:20:23.801481  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=10.126437
I20260812 06:20:23.850700  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.049s	user 0.026s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15300,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:23.851198  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=2.188937
I20260812 06:20:23.865211  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.014s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5268,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:23.865797  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e): perf score=1.000000
I20260812 06:20:24.000506  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.135s	user 0.108s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1409,"lbm_read_time_us":10658,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23849,"lbm_writes_lt_1ms":443,"mutex_wait_us":601,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9728,"update_count":2000}
I20260812 06:20:24.001036  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=10.126437
I20260812 06:20:24.046612  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.045s	user 0.022s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16522,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:24.047137  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=2.188937
I20260812 06:20:24.058007  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3938,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.058772  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e): perf score=1.000000
I20260812 06:20:24.199767  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.141s	user 0.108s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":107,"lbm_read_time_us":9767,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29059,"lbm_writes_lt_1ms":443,"mutex_wait_us":45,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2000}
I20260812 06:20:24.200358  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=10.126437
I20260812 06:20:24.251605  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.051s	user 0.016s	sys 0.023s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14209,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:24.252262  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=2.188937
I20260812 06:20:24.265153  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.013s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4515,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.265930  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushMRSOp(945f62e34a934e53a09c250c63b4689e): perf score=1.000000
I20260812 06:20:24.309903  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushMRSOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.044s	user 0.032s	sys 0.001s Metrics: {"bytes_written":1193504,"cfile_init":1,"dirs.queue_time_us":105,"dirs.run_cpu_time_us":324,"dirs.run_wall_time_us":1294,"drs_written":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2054,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:24.311188  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling LogGCOp(945f62e34a934e53a09c250c63b4689e): free 124710292 bytes of WAL
I20260812 06:20:24.311534  2414 log_reader.cc:385] T 945f62e34a934e53a09c250c63b4689e: removed 12 log segments from log reader
I20260812 06:20:24.311599  2414 log.cc:1079] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/945f62e34a934e53a09c250c63b4689e/wal-000000002 (ops 7-11)
I20260812 06:20:24.311645  2414 log.cc:1079] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/945f62e34a934e53a09c250c63b4689e/wal-000000003 (ops 12-16)
I20260812 06:20:24.311674  2414 log.cc:1079] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/945f62e34a934e53a09c250c63b4689e/wal-000000004 (ops 17-21)
I20260812 06:20:24.311708  2414 log.cc:1079] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/945f62e34a934e53a09c250c63b4689e/wal-000000005 (ops 22-26)
I20260812 06:20:24.311734  2414 log.cc:1079] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/945f62e34a934e53a09c250c63b4689e/wal-000000006 (ops 27-31)
I20260812 06:20:24.311770  2414 log.cc:1079] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/945f62e34a934e53a09c250c63b4689e/wal-000000007 (ops 32-36)
I20260812 06:20:24.311795  2414 log.cc:1079] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/945f62e34a934e53a09c250c63b4689e/wal-000000008 (ops 37-41)
I20260812 06:20:24.311825  2414 log.cc:1079] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/945f62e34a934e53a09c250c63b4689e/wal-000000009 (ops 42-46)
I20260812 06:20:24.311856  2414 log.cc:1079] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/945f62e34a934e53a09c250c63b4689e/wal-000000010 (ops 47-51)
I20260812 06:20:24.311880  2414 log.cc:1079] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/945f62e34a934e53a09c250c63b4689e/wal-000000011 (ops 52-56)
I20260812 06:20:24.311909  2414 log.cc:1079] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/945f62e34a934e53a09c250c63b4689e/wal-000000012 (ops 57-61)
I20260812 06:20:24.311940  2414 log.cc:1079] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/945f62e34a934e53a09c250c63b4689e/wal-000000013 (ops 62-66)
I20260812 06:20:24.337464  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: LogGCOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.026s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:20:24.337951  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling UndoDeltaBlockGCOp(945f62e34a934e53a09c250c63b4689e): 462 bytes on disk
I20260812 06:20:24.338455  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: UndoDeltaBlockGCOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4}
I20260812 06:20:24.338961  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=3.181125
I20260812 06:20:24.359098  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.020s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4668,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:24.359818  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=2.188937
I20260812 06:20:24.371101  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3885,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:24.371762  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e): perf score=1.000000
I20260812 06:20:24.588932  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.217s	user 0.137s	sys 0.080s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836362,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":819,"lbm_read_time_us":13695,"lbm_reads_lt_1ms":674,"lbm_write_time_us":38379,"lbm_writes_lt_1ms":643,"mutex_wait_us":578,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":17536,"thread_start_us":113,"threads_started":1,"update_count":3000}
I20260812 06:20:24.589999  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=14.095187
I20260812 06:20:24.644013  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.054s	user 0.024s	sys 0.025s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22843,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:24.645098  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e): perf score=1.000000
I20260812 06:20:24.815564  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.170s	user 0.106s	sys 0.052s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631193,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":314,"lbm_read_time_us":11520,"lbm_reads_lt_1ms":463,"lbm_write_time_us":26006,"lbm_writes_lt_1ms":443,"mutex_wait_us":78,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:24.816159  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=14.095187
I20260812 06:20:24.876295  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.060s	user 0.032s	sys 0.018s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22955,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:24.876904  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=2.188937
I20260812 06:20:24.889526  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4123,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:24.890077  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e): perf score=1.000000
I20260812 06:20:25.085242  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.195s	user 0.127s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":369,"lbm_read_time_us":13643,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27915,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":26368,"update_count":2500}
I20260812 06:20:25.085836  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=14.095187
I20260812 06:20:25.151712  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.066s	user 0.025s	sys 0.025s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22035,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:25.152453  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=2.188937
I20260812 06:20:25.166116  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5234,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.168972  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e): perf score=1.000000
I20260812 06:20:25.343575  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.174s	user 0.128s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":629,"lbm_read_time_us":13099,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33064,"lbm_writes_lt_1ms":543,"mutex_wait_us":314,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":66944,"update_count":2500}
I20260812 06:20:25.344146  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=10.126437
I20260812 06:20:25.389200  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.045s	user 0.020s	sys 0.011s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15463,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:25.389895  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=2.188937
I20260812 06:20:25.404086  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.014s	user 0.003s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4881,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.405282  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e): perf score=1.000000
I20260812 06:20:25.547986  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.142s	user 0.108s	sys 0.034s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":238,"lbm_read_time_us":11678,"lbm_reads_lt_1ms":468,"lbm_write_time_us":25228,"lbm_writes_lt_1ms":443,"mutex_wait_us":35,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":42112,"update_count":2000}
I20260812 06:20:25.548893  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=10.126437
I20260812 06:20:25.593382  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.044s	user 0.019s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17328,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:25.594030  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=2.188937
I20260812 06:20:25.607986  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.014s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5141,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.608585  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e): perf score=1.000000
I20260812 06:20:25.749071  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.140s	user 0.106s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":349,"lbm_read_time_us":9017,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28544,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:20:25.749823  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=10.126437
I20260812 06:20:25.807327  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.057s	user 0.030s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16628,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:25.808113  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=2.188937
I20260812 06:20:25.820899  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.013s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4695,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:25.821611  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushMRSOp(945f62e34a934e53a09c250c63b4689e): perf score=1.000000
I20260812 06:20:25.865267  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushMRSOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.043s	user 0.029s	sys 0.001s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":88,"dirs.run_cpu_time_us":301,"dirs.run_wall_time_us":1478,"drs_written":1,"lbm_read_time_us":88,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1474,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:25.866248  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling LogGCOp(945f62e34a934e53a09c250c63b4689e): free 112239316 bytes of WAL
I20260812 06:20:25.866518  2414 log_reader.cc:385] T 945f62e34a934e53a09c250c63b4689e: removed 11 log segments from log reader
I20260812 06:20:25.866565  2414 log.cc:1079] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/945f62e34a934e53a09c250c63b4689e/wal-000000014 (ops 67-71)
I20260812 06:20:25.866595  2414 log.cc:1079] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/945f62e34a934e53a09c250c63b4689e/wal-000000015 (ops 72-76)
I20260812 06:20:25.866626  2414 log.cc:1079] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/945f62e34a934e53a09c250c63b4689e/wal-000000016 (ops 77-81)
I20260812 06:20:25.866655  2414 log.cc:1079] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/945f62e34a934e53a09c250c63b4689e/wal-000000017 (ops 82-86)
I20260812 06:20:25.866685  2414 log.cc:1079] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/945f62e34a934e53a09c250c63b4689e/wal-000000018 (ops 87-91)
I20260812 06:20:25.866724  2414 log.cc:1079] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/945f62e34a934e53a09c250c63b4689e/wal-000000019 (ops 92-96)
I20260812 06:20:25.866744  2414 log.cc:1079] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/945f62e34a934e53a09c250c63b4689e/wal-000000020 (ops 97-100)
I20260812 06:20:25.866775  2414 log.cc:1079] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/945f62e34a934e53a09c250c63b4689e/wal-000000021 (ops 101-105)
I20260812 06:20:25.866806  2414 log.cc:1079] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/945f62e34a934e53a09c250c63b4689e/wal-000000022 (ops 106-110)
I20260812 06:20:25.866837  2414 log.cc:1079] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/945f62e34a934e53a09c250c63b4689e/wal-000000023 (ops 111-115)
I20260812 06:20:25.866868  2414 log.cc:1079] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/945f62e34a934e53a09c250c63b4689e/wal-000000024 (ops 116-120)
I20260812 06:20:25.889161  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: LogGCOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.023s	user 0.000s	sys 0.019s Metrics: {}
I20260812 06:20:25.889583  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling UndoDeltaBlockGCOp(945f62e34a934e53a09c250c63b4689e): 448 bytes on disk
I20260812 06:20:25.890074  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: UndoDeltaBlockGCOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:20:25.890571  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=3.181125
I20260812 06:20:25.908496  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.018s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4562,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:25.909017  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=2.188937
I20260812 06:20:25.924706  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5385,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:25.925676  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e): perf score=1.000000
I20260812 06:20:26.121028  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.195s	user 0.124s	sys 0.068s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836361,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":4117,"lbm_read_time_us":13105,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32644,"lbm_writes_lt_1ms":643,"mutex_wait_us":101,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":151680,"thread_start_us":141,"threads_started":1,"update_count":3000}
I20260812 06:20:26.121878  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=14.095187
I20260812 06:20:26.178210  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.056s	user 0.030s	sys 0.017s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21752,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:26.178848  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e): perf score=1.000000
I20260812 06:20:26.345150  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.166s	user 0.088s	sys 0.064s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631193,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1498,"lbm_read_time_us":13261,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":462,"lbm_write_time_us":24432,"lbm_writes_lt_1ms":443,"mutex_wait_us":405,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2000}
I20260812 06:20:26.346000  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=14.095187
I20260812 06:20:26.395980  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.050s	user 0.031s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18277,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:26.396636  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=2.188937
I20260812 06:20:26.410163  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.013s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4798,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.410655  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e): perf score=1.000000
I20260812 06:20:26.616063  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.205s	user 0.129s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":167,"lbm_read_time_us":14019,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29361,"lbm_writes_lt_1ms":543,"mutex_wait_us":35,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":50944,"update_count":2500}
I20260812 06:20:26.616777  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=14.095187
I20260812 06:20:26.664819  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.048s	user 0.024s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21190,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:26.665380  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=2.188937
I20260812 06:20:26.677552  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4110,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.678025  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e): perf score=1.000000
I20260812 06:20:26.829737  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.151s	user 0.100s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1582,"lbm_read_time_us":9066,"lbm_reads_lt_1ms":568,"lbm_write_time_us":29310,"lbm_writes_lt_1ms":543,"mutex_wait_us":485,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10240,"update_count":2500}
I20260812 06:20:26.830361  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=10.126437
I20260812 06:20:26.863197  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.033s	user 0.013s	sys 0.018s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14129,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:26.863785  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=2.188937
I20260812 06:20:26.878485  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5518,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:26.878942  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e): perf score=1.000000
I20260812 06:20:27.011086  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.132s	user 0.112s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1244,"lbm_read_time_us":7549,"lbm_reads_lt_1ms":468,"lbm_write_time_us":24741,"lbm_writes_lt_1ms":443,"mutex_wait_us":331,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2000}
I20260812 06:20:27.012039  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=10.126437
I20260812 06:20:27.058406  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.046s	user 0.025s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17684,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:27.059060  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=2.188937
I20260812 06:20:27.069706  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3705,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.070286  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e): perf score=1.000000
I20260812 06:20:27.207067  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.136s	user 0.102s	sys 0.034s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":680,"lbm_read_time_us":9375,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25833,"lbm_writes_lt_1ms":443,"mutex_wait_us":319,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":664960,"update_count":2000}
I20260812 06:20:27.207572  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=10.126437
I20260812 06:20:27.256810  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.049s	user 0.033s	sys 0.006s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14431,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:27.257638  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=2.188937
I20260812 06:20:27.274789  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.017s	user 0.010s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6567,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.275440  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushMRSOp(945f62e34a934e53a09c250c63b4689e): perf score=1.000000
I20260812 06:20:27.313393  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushMRSOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.038s	user 0.021s	sys 0.006s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":246,"dirs.run_wall_time_us":1266,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1422,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28,"spinlock_wait_cycles":2432}
I20260812 06:20:27.314225  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling LogGCOp(945f62e34a934e53a09c250c63b4689e): free 115943329 bytes of WAL
I20260812 06:20:27.314503  2414 log_reader.cc:385] T 945f62e34a934e53a09c250c63b4689e: removed 11 log segments from log reader
I20260812 06:20:27.314556  2414 log.cc:1079] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/945f62e34a934e53a09c250c63b4689e/wal-000000025 (ops 121-125)
I20260812 06:20:27.314597  2414 log.cc:1079] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/945f62e34a934e53a09c250c63b4689e/wal-000000026 (ops 126-130)
I20260812 06:20:27.314631  2414 log.cc:1079] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/945f62e34a934e53a09c250c63b4689e/wal-000000027 (ops 131-135)
I20260812 06:20:27.314656  2414 log.cc:1079] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/945f62e34a934e53a09c250c63b4689e/wal-000000028 (ops 136-140)
I20260812 06:20:27.314687  2414 log.cc:1079] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/945f62e34a934e53a09c250c63b4689e/wal-000000029 (ops 141-145)
I20260812 06:20:27.314718  2414 log.cc:1079] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/945f62e34a934e53a09c250c63b4689e/wal-000000030 (ops 146-150)
I20260812 06:20:27.314749  2414 log.cc:1079] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/945f62e34a934e53a09c250c63b4689e/wal-000000031 (ops 151-155)
I20260812 06:20:27.314780  2414 log.cc:1079] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/945f62e34a934e53a09c250c63b4689e/wal-000000032 (ops 156-160)
I20260812 06:20:27.314812  2414 log.cc:1079] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/945f62e34a934e53a09c250c63b4689e/wal-000000033 (ops 161-165)
I20260812 06:20:27.314842  2414 log.cc:1079] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/945f62e34a934e53a09c250c63b4689e/wal-000000034 (ops 166-170)
I20260812 06:20:27.314872  2414 log.cc:1079] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/945f62e34a934e53a09c250c63b4689e/wal-000000035 (ops 171-175)
I20260812 06:20:27.339365  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: LogGCOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.025s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:20:27.339931  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=3.181125
I20260812 06:20:27.363751  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.024s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4319,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:27.364210  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling UndoDeltaBlockGCOp(945f62e34a934e53a09c250c63b4689e): 447 bytes on disk
I20260812 06:20:27.364604  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: UndoDeltaBlockGCOp(945f62e34a934e53a09c250c63b4689e) 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:27.365105  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=2.188937
I20260812 06:20:27.374670  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.009s	user 0.008s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3284,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:27.375152  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e): perf score=1.000000
I20260812 06:20:27.584944  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.210s	user 0.160s	sys 0.049s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836361,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":489,"lbm_read_time_us":15300,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35336,"lbm_writes_lt_1ms":643,"mutex_wait_us":44,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":15360,"thread_start_us":95,"threads_started":1,"update_count":3000}
I20260812 06:20:27.585520  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=15.087375
I20260812 06:20:27.627985  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.041s	user 0.026s	sys 0.012s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":18251,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:20:27.628546  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=2.188937
I20260812 06:20:27.647141  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.018s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4966,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:27.647596  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e): perf score=1.000000
I20260812 06:20:27.806998  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.159s	user 0.102s	sys 0.058s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733711,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":234,"lbm_read_time_us":11114,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27484,"lbm_writes_lt_1ms":543,"mutex_wait_us":68,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2500}
I20260812 06:20:27.807667  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=14.095187
I20260812 06:20:27.845700  2241 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.185s	user 1.816s	sys 0.184s
I20260812 06:20:27.850468  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.043s	user 0.025s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19841,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:27.850970  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e): perf score=2.188937
I20260812 06:20:27.860508  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: FlushDeltaMemStoresOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3971,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:27.860950  2518 maintenance_manager.cc:419] P bbabfde0b3c64c2494b4e9d8875fb432: Scheduling MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e): perf score=1.000000
I20260812 06:20:27.899451  2241 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.053s	user 0.000s	sys 0.002s
I20260812 06:20:27.900079  2241 tablet_server.cc:179] TabletServer@127.2.48.65:0 shutting down...
I20260812 06:20:28.005388  2414 maintenance_manager.cc:643] P bbabfde0b3c64c2494b4e9d8875fb432: MajorDeltaCompactionOp(945f62e34a934e53a09c250c63b4689e) complete. Timing: real 0.144s	user 0.096s	sys 0.048s Metrics: {"cfile_cache_hit":24,"cfile_cache_hit_bytes":3377140,"cfile_cache_miss":508,"cfile_cache_miss_bytes":21356585,"cfile_init":5,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":902,"lbm_read_time_us":11409,"lbm_reads_lt_1ms":528,"lbm_write_time_us":22474,"lbm_writes_lt_1ms":543,"mutex_wait_us":276,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":68480,"update_count":2500}
I20260812 06:20:28.005988  2241 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:28.006462  2241 tablet_replica.cc:333] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432: stopping tablet replica
I20260812 06:20:28.006686  2241 raft_consensus.cc:2243] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:28.006902  2241 raft_consensus.cc:2272] T 945f62e34a934e53a09c250c63b4689e P bbabfde0b3c64c2494b4e9d8875fb432 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:28.022760  2241 tablet_server.cc:196] TabletServer@127.2.48.65:0 shutdown complete.
I20260812 06:20:28.053982  2241 master.cc:562] Master@127.2.48.126:34399 shutting down...
I20260812 06:20:28.057616  2241 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 0d29a8c2ed594593bce840c3255edfb8 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:28.057821  2241 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 0d29a8c2ed594593bce840c3255edfb8 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:28.057879  2241 tablet_replica.cc:333] T 00000000000000000000000000000000 P 0d29a8c2ed594593bce840c3255edfb8: stopping tablet replica
I20260812 06:20:28.070469  2241 master.cc:584] Master@127.2.48.126:34399 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5801 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:20:28.152097  2241 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.2.48.126:36579
I20260812 06:20:28.152488  2241 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:28.154395  2585 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:20:28.154558  2590 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:20:28.154412  2580 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:20:28.154623  2241 server_base.cc:1061] running on GCE node
I20260812 06:20:28.154894  2241 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:28.154945  2241 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:20:28.154965  2241 hybrid_clock.cc:648] HybridClock initialized: now 1786515628154965 us; error 0 us; skew 500 ppm
I20260812 06:20:28.155829  2241 webserver.cc:533] Webserver started at http://127.2.48.126:39455/ using document root <none> and password file <none>
I20260812 06:20:28.155993  2241 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:28.156044  2241 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:28.156116  2241 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:28.156486  2241 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/master-0-root/instance:
uuid: "3df6abf0114641219ffb9816b8f6ca4e"
format_stamp: "Formatted at 2026-08-12 06:20:28 on dist-test-slave-t7g5"
I20260812 06:20:28.157954  2241 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:28.159014  2597 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:20:28.159243  2241 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:28.159317  2241 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/master-0-root
uuid: "3df6abf0114641219ffb9816b8f6ca4e"
format_stamp: "Formatted at 2026-08-12 06:20:28 on dist-test-slave-t7g5"
I20260812 06:20:28.159384  2241 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-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:20:28.184967  2241 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:28.185397  2241 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:28.190243  2241 rpc_server.cc:307] RPC server started. Bound to: 127.2.48.126:36579
I20260812 06:20:28.204650  2689 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.2.48.126:36579 every 8 connection(s)
I20260812 06:20:28.205224  2694 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:20:28.207137  2694 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 3df6abf0114641219ffb9816b8f6ca4e: Bootstrap starting.
I20260812 06:20:28.207903  2694 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 3df6abf0114641219ffb9816b8f6ca4e: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:28.209237  2694 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 3df6abf0114641219ffb9816b8f6ca4e: No bootstrap required, opened a new log
I20260812 06:20:28.209910  2694 raft_consensus.cc:359] T 00000000000000000000000000000000 P 3df6abf0114641219ffb9816b8f6ca4e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3df6abf0114641219ffb9816b8f6ca4e" member_type: VOTER }
I20260812 06:20:28.210013  2694 raft_consensus.cc:385] T 00000000000000000000000000000000 P 3df6abf0114641219ffb9816b8f6ca4e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:28.210045  2694 raft_consensus.cc:740] T 00000000000000000000000000000000 P 3df6abf0114641219ffb9816b8f6ca4e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 3df6abf0114641219ffb9816b8f6ca4e, State: Initialized, Role: FOLLOWER
I20260812 06:20:28.210187  2694 consensus_queue.cc:260] T 00000000000000000000000000000000 P 3df6abf0114641219ffb9816b8f6ca4e [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: "3df6abf0114641219ffb9816b8f6ca4e" member_type: VOTER }
I20260812 06:20:28.210276  2694 raft_consensus.cc:399] T 00000000000000000000000000000000 P 3df6abf0114641219ffb9816b8f6ca4e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:28.210316  2694 raft_consensus.cc:493] T 00000000000000000000000000000000 P 3df6abf0114641219ffb9816b8f6ca4e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:28.210367  2694 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 3df6abf0114641219ffb9816b8f6ca4e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:28.211093  2694 raft_consensus.cc:515] T 00000000000000000000000000000000 P 3df6abf0114641219ffb9816b8f6ca4e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3df6abf0114641219ffb9816b8f6ca4e" member_type: VOTER }
I20260812 06:20:28.211221  2694 leader_election.cc:304] T 00000000000000000000000000000000 P 3df6abf0114641219ffb9816b8f6ca4e [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: 3df6abf0114641219ffb9816b8f6ca4e; no voters: 
I20260812 06:20:28.211414  2694 leader_election.cc:290] T 00000000000000000000000000000000 P 3df6abf0114641219ffb9816b8f6ca4e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:28.211555  2697 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 3df6abf0114641219ffb9816b8f6ca4e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:28.211766  2697 raft_consensus.cc:697] T 00000000000000000000000000000000 P 3df6abf0114641219ffb9816b8f6ca4e [term 1 LEADER]: Becoming Leader. State: Replica: 3df6abf0114641219ffb9816b8f6ca4e, State: Running, Role: LEADER
I20260812 06:20:28.211902  2694 sys_catalog.cc:565] T 00000000000000000000000000000000 P 3df6abf0114641219ffb9816b8f6ca4e [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:28.211954  2697 consensus_queue.cc:237] T 00000000000000000000000000000000 P 3df6abf0114641219ffb9816b8f6ca4e [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: "3df6abf0114641219ffb9816b8f6ca4e" member_type: VOTER }
I20260812 06:20:28.212380  2698 sys_catalog.cc:455] T 00000000000000000000000000000000 P 3df6abf0114641219ffb9816b8f6ca4e [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "3df6abf0114641219ffb9816b8f6ca4e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3df6abf0114641219ffb9816b8f6ca4e" member_type: VOTER } }
I20260812 06:20:28.212404  2699 sys_catalog.cc:455] T 00000000000000000000000000000000 P 3df6abf0114641219ffb9816b8f6ca4e [sys.catalog]: SysCatalogTable state changed. Reason: New leader 3df6abf0114641219ffb9816b8f6ca4e. Latest consensus state: current_term: 1 leader_uuid: "3df6abf0114641219ffb9816b8f6ca4e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3df6abf0114641219ffb9816b8f6ca4e" member_type: VOTER } }
I20260812 06:20:28.212638  2699 sys_catalog.cc:458] T 00000000000000000000000000000000 P 3df6abf0114641219ffb9816b8f6ca4e [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:28.212551  2698 sys_catalog.cc:458] T 00000000000000000000000000000000 P 3df6abf0114641219ffb9816b8f6ca4e [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:28.213066  2707 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:28.213897  2707 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:28.214161  2241 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:28.216071  2707 catalog_manager.cc:1383] Generated new cluster ID: 757b7fd530cf48fa8dfb969d687c0fc5
I20260812 06:20:28.216140  2707 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:28.223385  2707 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:28.224072  2707 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:28.230154  2707 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 3df6abf0114641219ffb9816b8f6ca4e: Generated new TSK 0
I20260812 06:20:28.230425  2707 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:28.246999  2241 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:28.248960  2729 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:20:28.249145  2731 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:20:28.249392  2241 server_base.cc:1061] running on GCE node
W20260812 06:20:28.249465  2735 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:20:28.249680  2241 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:28.249729  2241 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:20:28.249755  2241 hybrid_clock.cc:648] HybridClock initialized: now 1786515628249755 us; error 0 us; skew 500 ppm
I20260812 06:20:28.250593  2241 webserver.cc:533] Webserver started at http://127.2.48.65:43247/ using document root <none> and password file <none>
I20260812 06:20:28.250769  2241 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:28.250828  2241 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:28.250906  2241 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:28.251292  2241 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root/instance:
uuid: "97c87204b6204e988bc18fac693f2608"
format_stamp: "Formatted at 2026-08-12 06:20:28 on dist-test-slave-t7g5"
I20260812 06:20:28.252835  2241 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:28.256337  2743 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:20:28.256650  2241 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:20:28.256740  2241 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root
uuid: "97c87204b6204e988bc18fac693f2608"
format_stamp: "Formatted at 2026-08-12 06:20:28 on dist-test-slave-t7g5"
I20260812 06:20:28.256831  2241 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-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:20:28.271497  2241 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:28.271878  2241 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:28.272168  2241 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:28.272605  2241 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:28.272641  2241 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:28.272676  2241 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:28.272696  2241 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:28.276857  2241 rpc_server.cc:307] RPC server started. Bound to: 127.2.48.65:33689
I20260812 06:20:28.276902  2846 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.2.48.65:33689 every 8 connection(s)
I20260812 06:20:28.286115  2847 heartbeater.cc:344] Connected to a master server at 127.2.48.126:36579
I20260812 06:20:28.286253  2847 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:28.286520  2847 heartbeater.cc:507] Master 127.2.48.126:36579 requested a full tablet report, sending...
I20260812 06:20:28.287258  2624 ts_manager.cc:194] Registered new tserver with Master: 97c87204b6204e988bc18fac693f2608 (127.2.48.65:33689)
I20260812 06:20:28.287492  2241 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.010219435s
I20260812 06:20:28.288014  2624 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:58584
I20260812 06:20:28.295001  2624 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:58600:
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:20:28.305814  2795 tablet_service.cc:1511] Processing CreateTablet for tablet 5d1026cf73664dcea73d5a9382fd71b3 (DEFAULT_TABLE table=heavy-update-compaction-test [id=78622a61a2f2492c8b0e66a997ad8222]), partition=
I20260812 06:20:28.306113  2795 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 5d1026cf73664dcea73d5a9382fd71b3. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:28.308575  2864 tablet_bootstrap.cc:492] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Bootstrap starting.
I20260812 06:20:28.310089  2864 tablet_bootstrap.cc:654] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:28.311479  2864 tablet_bootstrap.cc:492] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: No bootstrap required, opened a new log
I20260812 06:20:28.311614  2864 ts_tablet_manager.cc:1403] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:20:28.312088  2864 raft_consensus.cc:359] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "97c87204b6204e988bc18fac693f2608" member_type: VOTER last_known_addr { host: "127.2.48.65" port: 33689 } }
I20260812 06:20:28.312299  2864 raft_consensus.cc:385] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:28.312376  2864 raft_consensus.cc:740] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 97c87204b6204e988bc18fac693f2608, State: Initialized, Role: FOLLOWER
I20260812 06:20:28.312520  2864 consensus_queue.cc:260] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608 [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: "97c87204b6204e988bc18fac693f2608" member_type: VOTER last_known_addr { host: "127.2.48.65" port: 33689 } }
I20260812 06:20:28.312609  2864 raft_consensus.cc:399] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:28.312670  2864 raft_consensus.cc:493] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:28.312703  2864 raft_consensus.cc:3060] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:28.313520  2864 raft_consensus.cc:515] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "97c87204b6204e988bc18fac693f2608" member_type: VOTER last_known_addr { host: "127.2.48.65" port: 33689 } }
I20260812 06:20:28.313694  2864 leader_election.cc:304] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608 [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: 97c87204b6204e988bc18fac693f2608; no voters: 
I20260812 06:20:28.313897  2864 leader_election.cc:290] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:28.314145  2867 raft_consensus.cc:2804] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:28.314236  2864 ts_tablet_manager.cc:1434] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:20:28.314296  2867 raft_consensus.cc:697] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608 [term 1 LEADER]: Becoming Leader. State: Replica: 97c87204b6204e988bc18fac693f2608, State: Running, Role: LEADER
I20260812 06:20:28.314356  2847 heartbeater.cc:499] Master 127.2.48.126:36579 was elected leader, sending a full tablet report...
I20260812 06:20:28.314742  2867 consensus_queue.cc:237] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608 [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: "97c87204b6204e988bc18fac693f2608" member_type: VOTER last_known_addr { host: "127.2.48.65" port: 33689 } }
I20260812 06:20:28.316362  2624 catalog_manager.cc:5719] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608 reported cstate change: term changed from 0 to 1, leader changed from <none> to 97c87204b6204e988bc18fac693f2608 (127.2.48.65). New cstate: current_term: 1 leader_uuid: "97c87204b6204e988bc18fac693f2608" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "97c87204b6204e988bc18fac693f2608" member_type: VOTER last_known_addr { host: "127.2.48.65" port: 33689 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:28.378957  2241 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.057s	user 0.012s	sys 0.013s
I20260812 06:20:28.527765  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushMRSOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=19.054940
I20260812 06:20:28.678599  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushMRSOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.151s	user 0.130s	sys 0.020s Metrics: {"bytes_written":12307491,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":185,"dirs.run_wall_time_us":778,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38074,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:20:28.679353  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling LogGCOp(5d1026cf73664dcea73d5a9382fd71b3): free 20743880 bytes of WAL
I20260812 06:20:28.679590  2753 log_reader.cc:385] T 5d1026cf73664dcea73d5a9382fd71b3: removed 2 log segments from log reader
I20260812 06:20:28.679653  2753 log.cc:1079] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/5d1026cf73664dcea73d5a9382fd71b3/wal-000000001 (ops 1-6)
I20260812 06:20:28.679694  2753 log.cc:1079] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/5d1026cf73664dcea73d5a9382fd71b3/wal-000000002 (ops 7-11)
I20260812 06:20:28.684988  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: LogGCOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.005s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:20:28.685716  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling UndoDeltaBlockGCOp(5d1026cf73664dcea73d5a9382fd71b3): 16411397 bytes on disk
I20260812 06:20:28.686359  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: UndoDeltaBlockGCOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":91,"lbm_reads_lt_1ms":4}
I20260812 06:20:28.686858  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=2.188937
I20260812 06:20:28.704986  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.018s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6368,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:28.705616  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling MajorDeltaCompactionOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=1.000000
I20260812 06:20:28.850291  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: MajorDeltaCompactionOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.144s	user 0.103s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":540,"lbm_read_time_us":9638,"lbm_reads_lt_1ms":460,"lbm_write_time_us":24957,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":243,"threads_started":5,"update_count":2000}
I20260812 06:20:28.850831  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=11.118625
I20260812 06:20:28.888187  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.037s	user 0.018s	sys 0.016s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":15778,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:28.888664  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=2.188937
I20260812 06:20:28.914515  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.026s	user 0.012s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4848,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:28.915021  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=2.188937
I20260812 06:20:28.928085  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.013s	user 0.008s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4702,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:28.928653  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling MajorDeltaCompactionOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=1.000000
I20260812 06:20:29.092957  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: MajorDeltaCompactionOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.164s	user 0.125s	sys 0.024s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774801,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":2034,"lbm_read_time_us":10883,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27595,"lbm_writes_lt_1ms":543,"mutex_wait_us":436,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2500}
I20260812 06:20:29.093888  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=14.095187
I20260812 06:20:29.139559  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.045s	user 0.023s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17931,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:29.140424  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=2.188937
I20260812 06:20:29.151450  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3918,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:29.151976  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling MajorDeltaCompactionOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=1.000000
I20260812 06:20:29.306185  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: MajorDeltaCompactionOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.154s	user 0.126s	sys 0.023s 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":190,"lbm_read_time_us":10007,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29358,"lbm_writes_lt_1ms":543,"mutex_wait_us":66,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:20:29.306964  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=12.110812
I20260812 06:20:29.349722  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.043s	user 0.034s	sys 0.008s Metrics: {"bytes_written":13620265,"delete_count":0,"lbm_write_time_us":18327,"lbm_writes_lt_1ms":335,"reinsert_count":0,"update_count":1660}
I20260812 06:20:29.350323  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=1.196750
I20260812 06:20:29.361073  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":2789855,"delete_count":0,"lbm_write_time_us":3497,"lbm_writes_lt_1ms":71,"reinsert_count":0,"update_count":340}
I20260812 06:20:29.361789  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling MajorDeltaCompactionOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=1.000000
I20260812 06:20:29.505625  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: MajorDeltaCompactionOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.144s	user 0.095s	sys 0.049s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672248,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":139,"lbm_read_time_us":11149,"lbm_reads_lt_1ms":468,"lbm_write_time_us":24377,"lbm_writes_lt_1ms":443,"mutex_wait_us":67,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2000}
I20260812 06:20:29.507869  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=10.126437
I20260812 06:20:29.547912  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.039s	user 0.025s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16448,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:29.548480  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=2.188937
I20260812 06:20:29.560796  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4751,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:29.561249  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling MajorDeltaCompactionOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=1.000000
I20260812 06:20:29.701388  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: MajorDeltaCompactionOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.140s	user 0.087s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1342,"lbm_read_time_us":9724,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26257,"lbm_writes_lt_1ms":443,"mutex_wait_us":345,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:20:29.702026  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=10.126437
I20260812 06:20:29.747090  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.045s	user 0.020s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15661,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:29.747860  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=2.188937
I20260812 06:20:29.765626  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.017s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6737,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:29.766448  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling MajorDeltaCompactionOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=1.000000
I20260812 06:20:29.900365  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: MajorDeltaCompactionOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.134s	user 0.100s	sys 0.033s 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":897,"lbm_read_time_us":10492,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25997,"lbm_writes_lt_1ms":443,"mutex_wait_us":280,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2000}
I20260812 06:20:29.900880  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=10.126437
I20260812 06:20:29.947458  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.046s	user 0.009s	sys 0.028s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":19439,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:29.948235  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=2.188937
I20260812 06:20:29.959882  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4382,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:29.960553  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushMRSOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=1.000000
I20260812 06:20:29.987703  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushMRSOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.027s	user 0.021s	sys 0.003s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":93,"dirs.run_cpu_time_us":218,"dirs.run_wall_time_us":1124,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1445,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:20:29.988592  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling LogGCOp(5d1026cf73664dcea73d5a9382fd71b3): free 124257246 bytes of WAL
I20260812 06:20:29.988835  2753 log_reader.cc:385] T 5d1026cf73664dcea73d5a9382fd71b3: removed 12 log segments from log reader
I20260812 06:20:29.988898  2753 log.cc:1079] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/5d1026cf73664dcea73d5a9382fd71b3/wal-000000003 (ops 12-16)
I20260812 06:20:29.988942  2753 log.cc:1079] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/5d1026cf73664dcea73d5a9382fd71b3/wal-000000004 (ops 17-21)
I20260812 06:20:29.988976  2753 log.cc:1079] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/5d1026cf73664dcea73d5a9382fd71b3/wal-000000005 (ops 22-26)
I20260812 06:20:29.989002  2753 log.cc:1079] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/5d1026cf73664dcea73d5a9382fd71b3/wal-000000006 (ops 27-31)
I20260812 06:20:29.989149  2753 log.cc:1079] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/5d1026cf73664dcea73d5a9382fd71b3/wal-000000007 (ops 32-36)
I20260812 06:20:29.989223  2753 log.cc:1079] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/5d1026cf73664dcea73d5a9382fd71b3/wal-000000008 (ops 37-41)
I20260812 06:20:29.989249  2753 log.cc:1079] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/5d1026cf73664dcea73d5a9382fd71b3/wal-000000009 (ops 42-46)
I20260812 06:20:29.989283  2753 log.cc:1079] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/5d1026cf73664dcea73d5a9382fd71b3/wal-000000010 (ops 47-51)
I20260812 06:20:29.989308  2753 log.cc:1079] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/5d1026cf73664dcea73d5a9382fd71b3/wal-000000011 (ops 52-56)
I20260812 06:20:29.989339  2753 log.cc:1079] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/5d1026cf73664dcea73d5a9382fd71b3/wal-000000012 (ops 57-61)
I20260812 06:20:29.989372  2753 log.cc:1079] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/5d1026cf73664dcea73d5a9382fd71b3/wal-000000013 (ops 62-66)
I20260812 06:20:29.989403  2753 log.cc:1079] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/5d1026cf73664dcea73d5a9382fd71b3/wal-000000014 (ops 67-70)
I20260812 06:20:30.014122  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: LogGCOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.025s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:20:30.014618  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=3.181125
I20260812 06:20:30.029932  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.015s	user 0.010s	sys 0.002s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":4182,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:30.030416  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling UndoDeltaBlockGCOp(5d1026cf73664dcea73d5a9382fd71b3): 473 bytes on disk
I20260812 06:20:30.030840  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: UndoDeltaBlockGCOp(5d1026cf73664dcea73d5a9382fd71b3) 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:30.031337  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=2.188937
I20260812 06:20:30.041265  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3605,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:30.041894  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling MajorDeltaCompactionOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=1.000000
I20260812 06:20:30.222216  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: MajorDeltaCompactionOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.180s	user 0.133s	sys 0.045s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877327,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":4607,"lbm_read_time_us":12423,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35537,"lbm_writes_lt_1ms":643,"mutex_wait_us":2049,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":81,"threads_started":1,"update_count":3000}
I20260812 06:20:30.223955  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=14.095187
I20260812 06:20:30.268360  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.044s	user 0.025s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19770,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:30.268788  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=2.188937
I20260812 06:20:30.282119  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3964,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:30.282819  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling MajorDeltaCompactionOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=1.000000
I20260812 06:20:30.447937  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: MajorDeltaCompactionOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.165s	user 0.110s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":645,"lbm_read_time_us":10201,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29998,"lbm_writes_lt_1ms":543,"mutex_wait_us":359,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":23936,"update_count":2500}
I20260812 06:20:30.448513  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=14.095187
I20260812 06:20:30.502815  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.054s	user 0.025s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22695,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:30.503572  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling MajorDeltaCompactionOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=1.000000
I20260812 06:20:30.646097  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: MajorDeltaCompactionOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.142s	user 0.094s	sys 0.045s 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":1438,"lbm_read_time_us":10332,"lbm_reads_lt_1ms":463,"lbm_write_time_us":22910,"lbm_writes_lt_1ms":443,"mutex_wait_us":318,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18816,"update_count":2000}
I20260812 06:20:30.646672  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=11.118625
I20260812 06:20:30.681026  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.034s	user 0.027s	sys 0.004s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15078,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:30.681499  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=2.188937
I20260812 06:20:30.704500  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.023s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5961,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":500}
I20260812 06:20:30.705013  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=2.188937
I20260812 06:20:30.714813  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3543,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:30.715418  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling MajorDeltaCompactionOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=1.000000
I20260812 06:20:30.898334  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: MajorDeltaCompactionOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.183s	user 0.109s	sys 0.059s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":236,"lbm_read_time_us":9798,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28201,"lbm_writes_lt_1ms":543,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":2500}
I20260812 06:20:30.898960  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=14.095187
I20260812 06:20:30.945724  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.047s	user 0.019s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":16836,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:30.946201  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=2.188937
I20260812 06:20:30.964063  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.018s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6659,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:30.964630  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling MajorDeltaCompactionOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=1.000000
I20260812 06:20:31.122078  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: MajorDeltaCompactionOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.157s	user 0.105s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1009,"lbm_read_time_us":10662,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28126,"lbm_writes_lt_1ms":543,"mutex_wait_us":132,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2500}
I20260812 06:20:31.122788  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=11.118625
I20260812 06:20:31.157789  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.035s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14885,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:31.158403  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=2.188937
I20260812 06:20:31.170913  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4316,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:31.171693  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling MajorDeltaCompactionOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=1.000000
I20260812 06:20:31.293047  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: MajorDeltaCompactionOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.121s	user 0.097s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":222,"lbm_read_time_us":7029,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22337,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2000}
I20260812 06:20:31.293632  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=10.126437
I20260812 06:20:31.332741  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.039s	user 0.029s	sys 0.004s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16076,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:31.333299  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushMRSOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=1.000000
I20260812 06:20:31.371039  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushMRSOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.038s	user 0.023s	sys 0.003s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":93,"dirs.run_cpu_time_us":229,"dirs.run_wall_time_us":1216,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1829,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:31.372033  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=3.181125
I20260812 06:20:31.386188  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.014s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4022,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:31.386864  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling LogGCOp(5d1026cf73664dcea73d5a9382fd71b3): free 112692366 bytes of WAL
I20260812 06:20:31.387181  2753 log_reader.cc:385] T 5d1026cf73664dcea73d5a9382fd71b3: removed 11 log segments from log reader
I20260812 06:20:31.387246  2753 log.cc:1079] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/5d1026cf73664dcea73d5a9382fd71b3/wal-000000015 (ops 71-75)
I20260812 06:20:31.387295  2753 log.cc:1079] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/5d1026cf73664dcea73d5a9382fd71b3/wal-000000016 (ops 76-80)
I20260812 06:20:31.387329  2753 log.cc:1079] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/5d1026cf73664dcea73d5a9382fd71b3/wal-000000017 (ops 81-85)
I20260812 06:20:31.387354  2753 log.cc:1079] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/5d1026cf73664dcea73d5a9382fd71b3/wal-000000018 (ops 86-90)
I20260812 06:20:31.387387  2753 log.cc:1079] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/5d1026cf73664dcea73d5a9382fd71b3/wal-000000019 (ops 91-95)
I20260812 06:20:31.387413  2753 log.cc:1079] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/5d1026cf73664dcea73d5a9382fd71b3/wal-000000020 (ops 96-100)
I20260812 06:20:31.387440  2753 log.cc:1079] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/5d1026cf73664dcea73d5a9382fd71b3/wal-000000021 (ops 101-105)
I20260812 06:20:31.387466  2753 log.cc:1079] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/5d1026cf73664dcea73d5a9382fd71b3/wal-000000022 (ops 106-110)
I20260812 06:20:31.387538  2753 log.cc:1079] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/5d1026cf73664dcea73d5a9382fd71b3/wal-000000023 (ops 111-115)
I20260812 06:20:31.387565  2753 log.cc:1079] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/5d1026cf73664dcea73d5a9382fd71b3/wal-000000024 (ops 116-120)
I20260812 06:20:31.387596  2753 log.cc:1079] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/5d1026cf73664dcea73d5a9382fd71b3/wal-000000025 (ops 121-125)
I20260812 06:20:31.413136  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: LogGCOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.026s	user 0.003s	sys 0.019s Metrics: {}
I20260812 06:20:31.413858  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=2.188937
I20260812 06:20:31.428179  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.014s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3959,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:31.428699  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=2.188937
I20260812 06:20:31.444826  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5896,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:31.445369  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling MajorDeltaCompactionOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=1.000000
I20260812 06:20:31.624359  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: MajorDeltaCompactionOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.179s	user 0.146s	sys 0.024s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877327,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":497,"lbm_read_time_us":11804,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34800,"lbm_writes_lt_1ms":643,"mutex_wait_us":32,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":81664,"thread_start_us":117,"threads_started":1,"update_count":3000}
I20260812 06:20:31.625160  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=14.095187
I20260812 06:20:31.674158  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.048s	user 0.032s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17614,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:31.674777  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=2.188937
I20260812 06:20:31.685370  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4109,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:31.685933  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling MajorDeltaCompactionOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=1.000000
I20260812 06:20:31.843314  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: MajorDeltaCompactionOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.157s	user 0.109s	sys 0.048s 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":496,"lbm_read_time_us":13943,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28162,"lbm_writes_lt_1ms":543,"mutex_wait_us":79,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":25728,"update_count":2500}
I20260812 06:20:31.844165  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling UndoDeltaBlockGCOp(5d1026cf73664dcea73d5a9382fd71b3): 462 bytes on disk
I20260812 06:20:31.844769  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: UndoDeltaBlockGCOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":80,"lbm_reads_lt_1ms":4}
I20260812 06:20:31.845366  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=11.118625
I20260812 06:20:31.888233  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.043s	user 0.024s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":19886,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:20:31.888772  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=2.188937
I20260812 06:20:31.903740  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5590,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:31.904227  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling MajorDeltaCompactionOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=1.000000
I20260812 06:20:32.058804  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: MajorDeltaCompactionOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.154s	user 0.110s	sys 0.043s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1106,"lbm_read_time_us":10805,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25794,"lbm_writes_lt_1ms":443,"mutex_wait_us":269,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2000}
I20260812 06:20:32.059532  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=11.118625
I20260812 06:20:32.104151  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.044s	user 0.022s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17542,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:32.105016  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=2.188937
I20260812 06:20:32.123965  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.019s	user 0.010s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7606,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:32.124421  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=2.188937
I20260812 06:20:32.144340  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.020s	user 0.006s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3502,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:32.144922  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling MajorDeltaCompactionOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=1.000000
I20260812 06:20:32.330878  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: MajorDeltaCompactionOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.186s	user 0.142s	sys 0.042s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":253,"lbm_read_time_us":12751,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29826,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2500}
I20260812 06:20:32.331808  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=11.118625
I20260812 06:20:32.362653  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.031s	user 0.017s	sys 0.013s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12973,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:32.363231  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=2.188937
I20260812 06:20:32.380930  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.018s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3801,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:32.381472  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling MajorDeltaCompactionOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=1.000000
I20260812 06:20:32.505343  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: MajorDeltaCompactionOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.124s	user 0.081s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":261,"lbm_read_time_us":7033,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25080,"lbm_writes_lt_1ms":443,"mutex_wait_us":17,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2000}
I20260812 06:20:32.506110  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=10.126437
I20260812 06:20:32.537919  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.032s	user 0.021s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13493,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:32.538476  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=2.188937
I20260812 06:20:32.552107  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4957,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:32.552882  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling MajorDeltaCompactionOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=1.000000
I20260812 06:20:32.690124  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: MajorDeltaCompactionOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.137s	user 0.116s	sys 0.020s 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":1390,"lbm_read_time_us":9516,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24657,"lbm_writes_lt_1ms":443,"mutex_wait_us":484,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2000}
I20260812 06:20:32.690735  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=10.126437
I20260812 06:20:32.741436  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.050s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17127,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:32.742156  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=2.188937
I20260812 06:20:32.758121  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.016s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5883,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:32.758713  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushMRSOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=1.000000
I20260812 06:20:32.788188  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushMRSOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.029s	user 0.023s	sys 0.003s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":191,"dirs.run_wall_time_us":1230,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1569,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:32.788928  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling LogGCOp(5d1026cf73664dcea73d5a9382fd71b3): free 121006685 bytes of WAL
I20260812 06:20:32.789182  2753 log_reader.cc:385] T 5d1026cf73664dcea73d5a9382fd71b3: removed 12 log segments from log reader
I20260812 06:20:32.789252  2753 log.cc:1079] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/5d1026cf73664dcea73d5a9382fd71b3/wal-000000026 (ops 126-130)
I20260812 06:20:32.789299  2753 log.cc:1079] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/5d1026cf73664dcea73d5a9382fd71b3/wal-000000027 (ops 131-135)
I20260812 06:20:32.789351  2753 log.cc:1079] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/5d1026cf73664dcea73d5a9382fd71b3/wal-000000028 (ops 136-140)
I20260812 06:20:32.789405  2753 log.cc:1079] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/5d1026cf73664dcea73d5a9382fd71b3/wal-000000029 (ops 141-144)
I20260812 06:20:32.789427  2753 log.cc:1079] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/5d1026cf73664dcea73d5a9382fd71b3/wal-000000030 (ops 145-149)
I20260812 06:20:32.789450  2753 log.cc:1079] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/5d1026cf73664dcea73d5a9382fd71b3/wal-000000031 (ops 150-154)
I20260812 06:20:32.789474  2753 log.cc:1079] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/5d1026cf73664dcea73d5a9382fd71b3/wal-000000032 (ops 155-159)
I20260812 06:20:32.789505  2753 log.cc:1079] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/5d1026cf73664dcea73d5a9382fd71b3/wal-000000033 (ops 160-164)
I20260812 06:20:32.789533  2753 log.cc:1079] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/5d1026cf73664dcea73d5a9382fd71b3/wal-000000034 (ops 165-169)
I20260812 06:20:32.789561  2753 log.cc:1079] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/5d1026cf73664dcea73d5a9382fd71b3/wal-000000035 (ops 170-174)
I20260812 06:20:32.789587  2753 log.cc:1079] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/5d1026cf73664dcea73d5a9382fd71b3/wal-000000036 (ops 175-179)
I20260812 06:20:32.789618  2753 log.cc:1079] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: Deleting log segment in path: /tmp/dist-test-taskitiz_E/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515622339764-2241-0/minicluster-data/ts-0-root/wals/5d1026cf73664dcea73d5a9382fd71b3/wal-000000037 (ops 180-184)
I20260812 06:20:32.818050  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: LogGCOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.029s	user 0.001s	sys 0.027s Metrics: {}
I20260812 06:20:32.818521  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=3.181125
I20260812 06:20:32.842375  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.024s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":6460,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:32.842911  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling UndoDeltaBlockGCOp(5d1026cf73664dcea73d5a9382fd71b3): 447 bytes on disk
I20260812 06:20:32.843665  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: UndoDeltaBlockGCOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":92,"lbm_reads_lt_1ms":4}
I20260812 06:20:32.844511  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=2.188937
I20260812 06:20:32.861297  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.017s	user 0.006s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6052,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:32.862000  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling MajorDeltaCompactionOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=1.000000
I20260812 06:20:33.039355  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: MajorDeltaCompactionOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.177s	user 0.124s	sys 0.052s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877326,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":588,"lbm_read_time_us":12171,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35957,"lbm_writes_lt_1ms":643,"mutex_wait_us":75,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7296,"thread_start_us":106,"threads_started":1,"update_count":3000}
I20260812 06:20:33.040326  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=14.095187
I20260812 06:20:33.094870  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.054s	user 0.033s	sys 0.015s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22186,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:33.095518  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=2.188937
I20260812 06:20:33.109395  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.014s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4615,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:33.110028  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling MajorDeltaCompactionOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=1.000000
I20260812 06:20:33.184533  2241 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.805s	user 1.757s	sys 0.126s
I20260812 06:20:33.247920  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: MajorDeltaCompactionOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.138s	user 0.092s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":553,"lbm_read_time_us":9733,"lbm_reads_lt_1ms":560,"lbm_write_time_us":25439,"lbm_writes_lt_1ms":543,"mutex_wait_us":102,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":31104,"update_count":2500}
I20260812 06:20:33.248183  2241 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.063s	user 0.005s	sys 0.000s
I20260812 06:20:33.248781  2848 maintenance_manager.cc:419] P 97c87204b6204e988bc18fac693f2608: Scheduling FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3): perf score=6.157687
I20260812 06:20:33.249135  2241 tablet_server.cc:179] TabletServer@127.2.48.65:0 shutting down...
I20260812 06:20:33.274614  2753 maintenance_manager.cc:643] P 97c87204b6204e988bc18fac693f2608: FlushDeltaMemStoresOp(5d1026cf73664dcea73d5a9382fd71b3) complete. Timing: real 0.026s	user 0.012s	sys 0.011s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":10688,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:20:33.275178  2241 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:33.275417  2241 tablet_replica.cc:333] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608: stopping tablet replica
I20260812 06:20:33.275559  2241 raft_consensus.cc:2243] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:33.275712  2241 raft_consensus.cc:2272] T 5d1026cf73664dcea73d5a9382fd71b3 P 97c87204b6204e988bc18fac693f2608 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:33.292048  2241 tablet_server.cc:196] TabletServer@127.2.48.65:0 shutdown complete.
I20260812 06:20:33.295128  2241 master.cc:562] Master@127.2.48.126:36579 shutting down...
I20260812 06:20:33.299118  2241 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 3df6abf0114641219ffb9816b8f6ca4e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:33.299398  2241 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 3df6abf0114641219ffb9816b8f6ca4e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:33.299480  2241 tablet_replica.cc:333] T 00000000000000000000000000000000 P 3df6abf0114641219ffb9816b8f6ca4e: stopping tablet replica
I20260812 06:20:33.312248  2241 master.cc:584] Master@127.2.48.126:36579 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5241 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11043 ms total)

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