[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:19:13.628414  9759 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.9.135.254:45391
I20260812 06:19:13.629720  9759 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:19:13.630448  9759 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:13.638815  9769 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:13.638815  9766 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:13.639369  9764 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:13.639495  9759 server_base.cc:1061] running on GCE node
I20260812 06:19:13.640162  9759 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:13.640304  9759 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:13.640339  9759 hybrid_clock.cc:648] HybridClock initialized: now 1786515553640337 us; error 0 us; skew 500 ppm
I20260812 06:19:13.643015  9759 webserver.cc:533] Webserver started at http://127.9.135.254:35069/ using document root <none> and password file <none>
I20260812 06:19:13.643644  9759 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:13.643728  9759 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:13.643953  9759 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:13.645967  9759 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/master-0-root/instance:
uuid: "40e160cc8d454b608b2f96fde903c5d5"
format_stamp: "Formatted at 2026-08-12 06:19:13 on dist-test-slave-g350"
I20260812 06:19:13.651024  9759 fs_manager.cc:696] Time spent creating directory manager: real 0.005s	user 0.004s	sys 0.000s
I20260812 06:19:13.655014  9775 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:13.657150  9759 fs_manager.cc:730] Time spent opening block manager: real 0.004s	user 0.004s	sys 0.001s
I20260812 06:19:13.657548  9759 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/master-0-root
uuid: "40e160cc8d454b608b2f96fde903c5d5"
format_stamp: "Formatted at 2026-08-12 06:19:13 on dist-test-slave-g350"
I20260812 06:19:13.657835  9759 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:13.683462  9759 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:13.684288  9759 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:19:13.684522  9759 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:13.694504  9759 rpc_server.cc:307] RPC server started. Bound to: 127.9.135.254:45391
I20260812 06:19:13.694800  9833 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.9.135.254:45391 every 8 connection(s)
I20260812 06:19:13.698096  9834 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:13.704818  9834 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 40e160cc8d454b608b2f96fde903c5d5: Bootstrap starting.
I20260812 06:19:13.707696  9834 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 40e160cc8d454b608b2f96fde903c5d5: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:13.709056  9834 log.cc:826] T 00000000000000000000000000000000 P 40e160cc8d454b608b2f96fde903c5d5: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:13.711501  9834 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 40e160cc8d454b608b2f96fde903c5d5: No bootstrap required, opened a new log
I20260812 06:19:13.714852  9834 raft_consensus.cc:359] T 00000000000000000000000000000000 P 40e160cc8d454b608b2f96fde903c5d5 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "40e160cc8d454b608b2f96fde903c5d5" member_type: VOTER }
I20260812 06:19:13.715112  9834 raft_consensus.cc:385] T 00000000000000000000000000000000 P 40e160cc8d454b608b2f96fde903c5d5 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:13.715159  9834 raft_consensus.cc:740] T 00000000000000000000000000000000 P 40e160cc8d454b608b2f96fde903c5d5 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 40e160cc8d454b608b2f96fde903c5d5, State: Initialized, Role: FOLLOWER
I20260812 06:19:13.715930  9834 consensus_queue.cc:260] T 00000000000000000000000000000000 P 40e160cc8d454b608b2f96fde903c5d5 [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: "40e160cc8d454b608b2f96fde903c5d5" member_type: VOTER }
I20260812 06:19:13.716114  9834 raft_consensus.cc:399] T 00000000000000000000000000000000 P 40e160cc8d454b608b2f96fde903c5d5 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:13.716223  9834 raft_consensus.cc:493] T 00000000000000000000000000000000 P 40e160cc8d454b608b2f96fde903c5d5 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:13.716354  9834 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 40e160cc8d454b608b2f96fde903c5d5 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:13.717345  9834 raft_consensus.cc:515] T 00000000000000000000000000000000 P 40e160cc8d454b608b2f96fde903c5d5 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "40e160cc8d454b608b2f96fde903c5d5" member_type: VOTER }
I20260812 06:19:13.717917  9834 leader_election.cc:304] T 00000000000000000000000000000000 P 40e160cc8d454b608b2f96fde903c5d5 [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: 40e160cc8d454b608b2f96fde903c5d5; no voters: 
I20260812 06:19:13.718303  9834 leader_election.cc:290] T 00000000000000000000000000000000 P 40e160cc8d454b608b2f96fde903c5d5 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:13.718546  9838 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 40e160cc8d454b608b2f96fde903c5d5 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:13.718825  9838 raft_consensus.cc:697] T 00000000000000000000000000000000 P 40e160cc8d454b608b2f96fde903c5d5 [term 1 LEADER]: Becoming Leader. State: Replica: 40e160cc8d454b608b2f96fde903c5d5, State: Running, Role: LEADER
I20260812 06:19:13.719465  9838 consensus_queue.cc:237] T 00000000000000000000000000000000 P 40e160cc8d454b608b2f96fde903c5d5 [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: "40e160cc8d454b608b2f96fde903c5d5" member_type: VOTER }
I20260812 06:19:13.719544  9834 sys_catalog.cc:565] T 00000000000000000000000000000000 P 40e160cc8d454b608b2f96fde903c5d5 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:13.722221  9759 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:13.722291  9840 sys_catalog.cc:455] T 00000000000000000000000000000000 P 40e160cc8d454b608b2f96fde903c5d5 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 40e160cc8d454b608b2f96fde903c5d5. Latest consensus state: current_term: 1 leader_uuid: "40e160cc8d454b608b2f96fde903c5d5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "40e160cc8d454b608b2f96fde903c5d5" member_type: VOTER } }
I20260812 06:19:13.722441  9840 sys_catalog.cc:458] T 00000000000000000000000000000000 P 40e160cc8d454b608b2f96fde903c5d5 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:13.722764  9839 sys_catalog.cc:455] T 00000000000000000000000000000000 P 40e160cc8d454b608b2f96fde903c5d5 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "40e160cc8d454b608b2f96fde903c5d5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "40e160cc8d454b608b2f96fde903c5d5" member_type: VOTER } }
I20260812 06:19:13.722867  9839 sys_catalog.cc:458] T 00000000000000000000000000000000 P 40e160cc8d454b608b2f96fde903c5d5 [sys.catalog]: This master's current role is: LEADER
W20260812 06:19:13.725152  9855 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 40e160cc8d454b608b2f96fde903c5d5: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:19:13.725402  9855 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:19:13.725556  9856 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:13.726563  9856 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:13.733162  9856 catalog_manager.cc:1383] Generated new cluster ID: 0be7de76b1224904baaba33e0d8f2962
I20260812 06:19:13.733273  9856 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:13.742308  9856 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:13.743616  9856 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:13.755967  9856 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 40e160cc8d454b608b2f96fde903c5d5: Generated new TSK 0
I20260812 06:19:13.756770  9856 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:13.787518  9759 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:13.791203  9861 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:13.791311  9865 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:13.791566  9867 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:13.791805  9759 server_base.cc:1061] running on GCE node
I20260812 06:19:13.792034  9759 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:13.792095  9759 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:13.792145  9759 hybrid_clock.cc:648] HybridClock initialized: now 1786515553792143 us; error 0 us; skew 500 ppm
I20260812 06:19:13.793489  9759 webserver.cc:533] Webserver started at http://127.9.135.193:35849/ using document root <none> and password file <none>
I20260812 06:19:13.793756  9759 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:13.793814  9759 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:13.793932  9759 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:13.794420  9759 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/instance:
uuid: "4d729f24e43d4eef9097b068c63ca1cb"
format_stamp: "Formatted at 2026-08-12 06:19:13 on dist-test-slave-g350"
I20260812 06:19:13.796414  9759 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.001s	sys 0.001s
I20260812 06:19:13.797725  9873 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:13.798039  9759 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:13.798110  9759 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root
uuid: "4d729f24e43d4eef9097b068c63ca1cb"
format_stamp: "Formatted at 2026-08-12 06:19:13 on dist-test-slave-g350"
I20260812 06:19:13.798223  9759 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:13.833807  9759 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:13.834319  9759 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:13.834874  9759 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:13.835814  9759 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:13.835917  9759 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:13.836004  9759 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:13.836051  9759 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:13.843844  9759 rpc_server.cc:307] RPC server started. Bound to: 127.9.135.193:35033
I20260812 06:19:13.843859  9945 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.9.135.193:35033 every 8 connection(s)
I20260812 06:19:13.858047  9946 heartbeater.cc:344] Connected to a master server at 127.9.135.254:45391
I20260812 06:19:13.858460  9946 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:13.859133  9946 heartbeater.cc:507] Master 127.9.135.254:45391 requested a full tablet report, sending...
I20260812 06:19:13.861163  9790 ts_manager.cc:194] Registered new tserver with Master: 4d729f24e43d4eef9097b068c63ca1cb (127.9.135.193:35033)
I20260812 06:19:13.861219  9759 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.016491701s
I20260812 06:19:13.863022  9790 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:49850
I20260812 06:19:13.875393  9790 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:49866:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:13.892997  9906 tablet_service.cc:1511] Processing CreateTablet for tablet 23e2936429da4ee79158aaadf5149d69 (DEFAULT_TABLE table=heavy-update-compaction-test [id=f576c38a27b54537956229994dbdf7cd]), partition=
I20260812 06:19:13.893579  9906 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 23e2936429da4ee79158aaadf5149d69. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:13.896996  9960 tablet_bootstrap.cc:492] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Bootstrap starting.
I20260812 06:19:13.898193  9960 tablet_bootstrap.cc:654] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:13.899682  9960 tablet_bootstrap.cc:492] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: No bootstrap required, opened a new log
I20260812 06:19:13.899844  9960 ts_tablet_manager.cc:1403] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:13.900465  9960 raft_consensus.cc:359] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4d729f24e43d4eef9097b068c63ca1cb" member_type: VOTER last_known_addr { host: "127.9.135.193" port: 35033 } }
I20260812 06:19:13.900591  9960 raft_consensus.cc:385] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:13.900617  9960 raft_consensus.cc:740] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4d729f24e43d4eef9097b068c63ca1cb, State: Initialized, Role: FOLLOWER
I20260812 06:19:13.900807  9960 consensus_queue.cc:260] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb [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: "4d729f24e43d4eef9097b068c63ca1cb" member_type: VOTER last_known_addr { host: "127.9.135.193" port: 35033 } }
I20260812 06:19:13.900900  9960 raft_consensus.cc:399] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:13.900956  9960 raft_consensus.cc:493] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:13.901026  9960 raft_consensus.cc:3060] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:13.902037  9960 raft_consensus.cc:515] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4d729f24e43d4eef9097b068c63ca1cb" member_type: VOTER last_known_addr { host: "127.9.135.193" port: 35033 } }
I20260812 06:19:13.902211  9960 leader_election.cc:304] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb [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: 4d729f24e43d4eef9097b068c63ca1cb; no voters: 
I20260812 06:19:13.902496  9960 leader_election.cc:290] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:13.902652  9963 raft_consensus.cc:2804] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:13.902935  9963 raft_consensus.cc:697] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb [term 1 LEADER]: Becoming Leader. State: Replica: 4d729f24e43d4eef9097b068c63ca1cb, State: Running, Role: LEADER
I20260812 06:19:13.903170  9946 heartbeater.cc:499] Master 127.9.135.254:45391 was elected leader, sending a full tablet report...
I20260812 06:19:13.903147  9963 consensus_queue.cc:237] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb [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: "4d729f24e43d4eef9097b068c63ca1cb" member_type: VOTER last_known_addr { host: "127.9.135.193" port: 35033 } }
I20260812 06:19:13.902930  9960 ts_tablet_manager.cc:1434] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Time spent starting tablet: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:19:13.907544  9790 catalog_manager.cc:5719] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb reported cstate change: term changed from 0 to 1, leader changed from <none> to 4d729f24e43d4eef9097b068c63ca1cb (127.9.135.193). New cstate: current_term: 1 leader_uuid: "4d729f24e43d4eef9097b068c63ca1cb" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4d729f24e43d4eef9097b068c63ca1cb" member_type: VOTER last_known_addr { host: "127.9.135.193" port: 35033 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:13.983070  9759 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.068s	user 0.021s	sys 0.005s
I20260812 06:19:14.095444  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushMRSOp(23e2936429da4ee79158aaadf5149d69): perf score=11.117440
I20260812 06:19:14.264478  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushMRSOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.169s	user 0.124s	sys 0.027s Metrics: {"bytes_written":11897249,"cfile_init":1,"compiler_manager_pool.queue_time_us":303,"delete_count":0,"dirs.queue_time_us":49,"dirs.run_cpu_time_us":232,"dirs.run_wall_time_us":1108,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":37425,"lbm_writes_lt_1ms":557,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"thread_start_us":198,"threads_started":1,"update_count":1450}
I20260812 06:19:14.265689  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling LogGCOp(23e2936429da4ee79158aaadf5149d69): free 11976772 bytes of WAL
I20260812 06:19:14.266021  9878 log_reader.cc:385] T 23e2936429da4ee79158aaadf5149d69: removed 1 log segments from log reader
I20260812 06:19:14.266100  9878 log.cc:1079] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/23e2936429da4ee79158aaadf5149d69/wal-000000001 (ops 1-6)
I20260812 06:19:14.268780  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: LogGCOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:14.269207  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=2.188937
I20260812 06:19:14.284411  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5418,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:14.285156  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling UndoDeltaBlockGCOp(23e2936429da4ee79158aaadf5149d69): 8616791 bytes on disk
I20260812 06:19:14.286229  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: UndoDeltaBlockGCOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":99,"lbm_reads_lt_1ms":4}
I20260812 06:19:14.286769  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling MajorDeltaCompactionOp(23e2936429da4ee79158aaadf5149d69): perf score=1.000000
I20260812 06:19:14.442473  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: MajorDeltaCompactionOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.156s	user 0.114s	sys 0.028s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20221071,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1068,"lbm_read_time_us":7630,"lbm_reads_lt_1ms":450,"lbm_write_time_us":28627,"lbm_writes_lt_1ms":433,"mutex_wait_us":153,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":3328,"thread_start_us":448,"threads_started":5,"update_count":1950}
I20260812 06:19:14.443396  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=10.126437
I20260812 06:19:14.499223  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.055s	user 0.029s	sys 0.020s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":21639,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:19:14.499936  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=2.188937
I20260812 06:19:14.514134  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5280,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:14.514753  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling MajorDeltaCompactionOp(23e2936429da4ee79158aaadf5149d69): perf score=1.000000
I20260812 06:19:14.657501  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: MajorDeltaCompactionOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.143s	user 0.134s	sys 0.008s 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":838,"lbm_read_time_us":10309,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29141,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":29184,"update_count":2000}
I20260812 06:19:14.658133  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=10.126437
I20260812 06:19:14.712503  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.054s	user 0.018s	sys 0.027s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":18184,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:14.713179  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=2.188937
I20260812 06:19:14.725333  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4654,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:14.725896  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling MajorDeltaCompactionOp(23e2936429da4ee79158aaadf5149d69): perf score=1.000000
I20260812 06:19:14.897171  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: MajorDeltaCompactionOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.171s	user 0.092s	sys 0.078s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":609,"lbm_read_time_us":12486,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29594,"lbm_writes_lt_1ms":443,"mutex_wait_us":103,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:14.897960  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=10.126437
I20260812 06:19:14.944706  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.046s	user 0.028s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19192,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:14.945295  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=2.188937
I20260812 06:19:14.958861  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4930,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:14.959489  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling MajorDeltaCompactionOp(23e2936429da4ee79158aaadf5149d69): perf score=1.000000
I20260812 06:19:15.098538  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: MajorDeltaCompactionOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.139s	user 0.115s	sys 0.023s 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":230,"lbm_read_time_us":9316,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26205,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":33792,"update_count":2000}
I20260812 06:19:15.099707  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=10.126437
I20260812 06:19:15.146644  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.047s	user 0.025s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20485,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:15.147300  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=2.188937
I20260812 06:19:15.162379  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5567,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:15.163137  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling MajorDeltaCompactionOp(23e2936429da4ee79158aaadf5149d69): perf score=1.000000
I20260812 06:19:15.294507  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: MajorDeltaCompactionOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.131s	user 0.114s	sys 0.015s 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":169,"lbm_read_time_us":9539,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27264,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2000}
I20260812 06:19:15.295459  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=10.126437
I20260812 06:19:15.352108  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.056s	user 0.020s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15459,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:15.352810  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=2.188937
I20260812 06:19:15.366001  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.013s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5524,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:15.366555  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling MajorDeltaCompactionOp(23e2936429da4ee79158aaadf5149d69): perf score=1.000000
I20260812 06:19:15.529738  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: MajorDeltaCompactionOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.163s	user 0.103s	sys 0.055s 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":848,"lbm_read_time_us":10860,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27293,"lbm_writes_lt_1ms":443,"mutex_wait_us":53,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14080,"update_count":2000}
I20260812 06:19:15.530586  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=10.126437
I20260812 06:19:15.586441  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.056s	user 0.018s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18721,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:15.587138  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=2.188937
I20260812 06:19:15.600469  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4318,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:15.601101  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling MajorDeltaCompactionOp(23e2936429da4ee79158aaadf5149d69): perf score=1.000000
I20260812 06:19:15.733705  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: MajorDeltaCompactionOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.132s	user 0.099s	sys 0.032s 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":401,"lbm_read_time_us":10607,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24673,"lbm_writes_lt_1ms":443,"mutex_wait_us":35,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":375936,"update_count":2000}
I20260812 06:19:15.734459  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=10.126437
I20260812 06:19:15.788126  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.053s	user 0.034s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":21382,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:15.788725  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=2.188937
I20260812 06:19:15.800330  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4312,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:15.801061  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushMRSOp(23e2936429da4ee79158aaadf5149d69): perf score=1.000000
I20260812 06:19:15.833657  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushMRSOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.032s	user 0.030s	sys 0.002s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":507,"dirs.run_wall_time_us":2822,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1846,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:15.834605  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling LogGCOp(23e2936429da4ee79158aaadf5149d69): free 129320441 bytes of WAL
I20260812 06:19:15.834899  9878 log_reader.cc:385] T 23e2936429da4ee79158aaadf5149d69: removed 13 log segments from log reader
I20260812 06:19:15.834946  9878 log.cc:1079] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/23e2936429da4ee79158aaadf5149d69/wal-000000002 (ops 7-11)
I20260812 06:19:15.834978  9878 log.cc:1079] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/23e2936429da4ee79158aaadf5149d69/wal-000000003 (ops 12-16)
I20260812 06:19:15.835053  9878 log.cc:1079] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/23e2936429da4ee79158aaadf5149d69/wal-000000004 (ops 17-21)
I20260812 06:19:15.835117  9878 log.cc:1079] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/23e2936429da4ee79158aaadf5149d69/wal-000000005 (ops 22-26)
I20260812 06:19:15.835182  9878 log.cc:1079] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/23e2936429da4ee79158aaadf5149d69/wal-000000006 (ops 27-31)
I20260812 06:19:15.835223  9878 log.cc:1079] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/23e2936429da4ee79158aaadf5149d69/wal-000000007 (ops 32-36)
I20260812 06:19:15.835263  9878 log.cc:1079] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/23e2936429da4ee79158aaadf5149d69/wal-000000008 (ops 37-41)
I20260812 06:19:15.835300  9878 log.cc:1079] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/23e2936429da4ee79158aaadf5149d69/wal-000000009 (ops 42-46)
I20260812 06:19:15.835345  9878 log.cc:1079] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/23e2936429da4ee79158aaadf5149d69/wal-000000010 (ops 47-50)
I20260812 06:19:15.835386  9878 log.cc:1079] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/23e2936429da4ee79158aaadf5149d69/wal-000000011 (ops 51-55)
I20260812 06:19:15.835424  9878 log.cc:1079] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/23e2936429da4ee79158aaadf5149d69/wal-000000012 (ops 56-60)
I20260812 06:19:15.835464  9878 log.cc:1079] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/23e2936429da4ee79158aaadf5149d69/wal-000000013 (ops 61-64)
I20260812 06:19:15.835502  9878 log.cc:1079] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/23e2936429da4ee79158aaadf5149d69/wal-000000014 (ops 65-69)
I20260812 06:19:15.870146  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: LogGCOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.035s	user 0.000s	sys 0.035s Metrics: {}
I20260812 06:19:15.870792  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=2.188937
I20260812 06:19:15.888228  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.017s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4704,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:15.888763  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling UndoDeltaBlockGCOp(23e2936429da4ee79158aaadf5149d69): 483 bytes on disk
I20260812 06:19:15.889302  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: UndoDeltaBlockGCOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4}
I20260812 06:19:15.889894  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=2.188937
I20260812 06:19:15.905354  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5716,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:15.906131  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling MajorDeltaCompactionOp(23e2936429da4ee79158aaadf5149d69): perf score=1.000000
I20260812 06:19:16.094575  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: MajorDeltaCompactionOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.188s	user 0.139s	sys 0.049s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836375,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":231,"lbm_read_time_us":14483,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36276,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":23936,"thread_start_us":84,"threads_started":1,"update_count":3000}
I20260812 06:19:16.095184  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=14.095187
I20260812 06:19:16.165063  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.070s	user 0.039s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":32758,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:16.165676  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=2.188937
I20260812 06:19:16.178682  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.013s	user 0.006s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4883,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:16.179239  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling MajorDeltaCompactionOp(23e2936429da4ee79158aaadf5149d69): perf score=1.000000
I20260812 06:19:16.356926  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: MajorDeltaCompactionOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.177s	user 0.126s	sys 0.037s 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":1953,"lbm_read_time_us":9520,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32627,"lbm_writes_lt_1ms":543,"mutex_wait_us":624,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":57472,"update_count":2500}
I20260812 06:19:16.358075  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=14.095187
I20260812 06:19:16.413021  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.055s	user 0.038s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25263,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:16.413786  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling MajorDeltaCompactionOp(23e2936429da4ee79158aaadf5149d69): perf score=1.000000
I20260812 06:19:16.585553  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: MajorDeltaCompactionOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.172s	user 0.127s	sys 0.037s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631192,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1111,"lbm_read_time_us":10349,"lbm_reads_lt_1ms":463,"lbm_write_time_us":29113,"lbm_writes_lt_1ms":443,"mutex_wait_us":326,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2000}
I20260812 06:19:16.586210  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=14.095187
I20260812 06:19:16.644716  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.058s	user 0.030s	sys 0.014s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":21058,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:16.645327  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=2.188937
I20260812 06:19:16.657744  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.012s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4454,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:16.658473  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling MajorDeltaCompactionOp(23e2936429da4ee79158aaadf5149d69): perf score=1.000000
I20260812 06:19:16.882994  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: MajorDeltaCompactionOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.224s	user 0.151s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733726,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":958,"lbm_read_time_us":11282,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35750,"lbm_writes_lt_1ms":543,"mutex_wait_us":321,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15616,"update_count":2500}
I20260812 06:19:16.883854  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=14.095187
I20260812 06:19:16.938162  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.054s	user 0.038s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23762,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:16.938930  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=2.188937
I20260812 06:19:16.956705  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.017s	user 0.013s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6559,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:16.957414  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling MajorDeltaCompactionOp(23e2936429da4ee79158aaadf5149d69): perf score=1.000000
I20260812 06:19:17.141988  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: MajorDeltaCompactionOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.184s	user 0.116s	sys 0.060s 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":4450,"lbm_read_time_us":12054,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34737,"lbm_writes_lt_1ms":543,"mutex_wait_us":3194,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2500}
I20260812 06:19:17.142733  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=11.118625
I20260812 06:19:17.189477  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.047s	user 0.034s	sys 0.009s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":19866,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:17.190564  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=2.188937
I20260812 06:19:17.215216  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.024s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4989,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:17.215884  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=2.188937
I20260812 06:19:17.228199  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4597,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:17.228933  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling MajorDeltaCompactionOp(23e2936429da4ee79158aaadf5149d69): perf score=1.000000
I20260812 06:19:17.393503  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: MajorDeltaCompactionOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.164s	user 0.122s	sys 0.037s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733835,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":429,"lbm_read_time_us":10924,"lbm_reads_lt_1ms":573,"lbm_write_time_us":33054,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2500}
I20260812 06:19:17.394308  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=11.118625
I20260812 06:19:17.431875  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.037s	user 0.032s	sys 0.003s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15420,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:17.432548  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=2.188937
I20260812 06:19:17.461855  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.029s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6024,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":450}
I20260812 06:19:17.462385  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=2.188937
I20260812 06:19:17.475464  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4977,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:17.476372  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushMRSOp(23e2936429da4ee79158aaadf5149d69): perf score=1.000000
I20260812 06:19:17.505141  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushMRSOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.029s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":54,"dirs.run_cpu_time_us":318,"dirs.run_wall_time_us":2054,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1914,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:17.506141  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling LogGCOp(23e2936429da4ee79158aaadf5149d69): free 128867509 bytes of WAL
I20260812 06:19:17.506462  9878 log_reader.cc:385] T 23e2936429da4ee79158aaadf5149d69: removed 13 log segments from log reader
I20260812 06:19:17.506544  9878 log.cc:1079] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/23e2936429da4ee79158aaadf5149d69/wal-000000015 (ops 70-74)
I20260812 06:19:17.506605  9878 log.cc:1079] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/23e2936429da4ee79158aaadf5149d69/wal-000000016 (ops 75-79)
I20260812 06:19:17.506664  9878 log.cc:1079] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/23e2936429da4ee79158aaadf5149d69/wal-000000017 (ops 80-84)
I20260812 06:19:17.506704  9878 log.cc:1079] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/23e2936429da4ee79158aaadf5149d69/wal-000000018 (ops 85-88)
I20260812 06:19:17.506745  9878 log.cc:1079] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/23e2936429da4ee79158aaadf5149d69/wal-000000019 (ops 89-93)
I20260812 06:19:17.506785  9878 log.cc:1079] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/23e2936429da4ee79158aaadf5149d69/wal-000000020 (ops 94-98)
I20260812 06:19:17.506825  9878 log.cc:1079] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/23e2936429da4ee79158aaadf5149d69/wal-000000021 (ops 99-103)
I20260812 06:19:17.506875  9878 log.cc:1079] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/23e2936429da4ee79158aaadf5149d69/wal-000000022 (ops 104-108)
I20260812 06:19:17.506917  9878 log.cc:1079] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/23e2936429da4ee79158aaadf5149d69/wal-000000023 (ops 109-112)
I20260812 06:19:17.506958  9878 log.cc:1079] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/23e2936429da4ee79158aaadf5149d69/wal-000000024 (ops 113-117)
I20260812 06:19:17.507009  9878 log.cc:1079] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/23e2936429da4ee79158aaadf5149d69/wal-000000025 (ops 118-122)
I20260812 06:19:17.507048  9878 log.cc:1079] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/23e2936429da4ee79158aaadf5149d69/wal-000000026 (ops 123-126)
I20260812 06:19:17.507158  9878 log.cc:1079] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/23e2936429da4ee79158aaadf5149d69/wal-000000027 (ops 127-131)
I20260812 06:19:17.536723  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: LogGCOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.030s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:19:17.537261  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling UndoDeltaBlockGCOp(23e2936429da4ee79158aaadf5149d69): 482 bytes on disk
I20260812 06:19:17.537981  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: UndoDeltaBlockGCOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":184,"lbm_reads_lt_1ms":4}
I20260812 06:19:17.538578  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=3.181125
I20260812 06:19:17.551656  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4635978,"delete_count":0,"lbm_write_time_us":5086,"lbm_writes_lt_1ms":116,"reinsert_count":0,"update_count":565}
I20260812 06:19:17.552194  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=2.188937
I20260812 06:19:17.573266  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.021s	user 0.006s	sys 0.011s Metrics: {"bytes_written":3569330,"delete_count":0,"lbm_write_time_us":4012,"lbm_writes_lt_1ms":90,"reinsert_count":0,"update_count":435}
I20260812 06:19:17.573989  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling MajorDeltaCompactionOp(23e2936429da4ee79158aaadf5149d69): perf score=1.000000
I20260812 06:19:17.827473  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: MajorDeltaCompactionOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.253s	user 0.196s	sys 0.052s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32938886,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":465,"lbm_read_time_us":17697,"lbm_reads_lt_1ms":775,"lbm_write_time_us":41711,"lbm_writes_lt_1ms":743,"mutex_wait_us":59,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":14464,"thread_start_us":110,"threads_started":1,"update_count":3500}
I20260812 06:19:17.828827  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=15.087375
I20260812 06:19:17.902248  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.073s	user 0.039s	sys 0.024s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":28963,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:17.902868  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=2.188937
I20260812 06:19:17.916769  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.014s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4696,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:17.917384  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=2.188937
I20260812 06:19:17.929239  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4431,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:17.930119  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling MajorDeltaCompactionOp(23e2936429da4ee79158aaadf5149d69): perf score=1.000000
I20260812 06:19:18.177205  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: MajorDeltaCompactionOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.247s	user 0.178s	sys 0.065s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836241,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1139,"lbm_read_time_us":16356,"lbm_reads_lt_1ms":673,"lbm_write_time_us":43291,"lbm_writes_lt_1ms":643,"mutex_wait_us":122,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":25472,"update_count":3000}
I20260812 06:19:18.178579  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=14.095187
I20260812 06:19:18.236541  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.058s	user 0.036s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23207,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:18.237119  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling MajorDeltaCompactionOp(23e2936429da4ee79158aaadf5149d69): perf score=1.000000
I20260812 06:19:18.414881  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: MajorDeltaCompactionOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.178s	user 0.107s	sys 0.060s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631192,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":658,"lbm_read_time_us":13519,"lbm_reads_lt_1ms":463,"lbm_write_time_us":27745,"lbm_writes_lt_1ms":443,"mutex_wait_us":288,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16128,"update_count":2000}
I20260812 06:19:18.415696  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=14.095187
I20260812 06:19:18.470219  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.054s	user 0.028s	sys 0.020s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":22044,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:18.470829  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=2.188937
I20260812 06:19:18.483855  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4631,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:18.484417  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling MajorDeltaCompactionOp(23e2936429da4ee79158aaadf5149d69): perf score=1.000000
I20260812 06:19:18.682402  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: MajorDeltaCompactionOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.198s	user 0.118s	sys 0.071s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733720,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":614,"lbm_read_time_us":12694,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30466,"lbm_writes_lt_1ms":543,"mutex_wait_us":251,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":2500}
I20260812 06:19:18.683494  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=11.118625
I20260812 06:19:18.724622  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.041s	user 0.021s	sys 0.017s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":18160,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:18.725515  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=2.188937
I20260812 06:19:18.740010  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.014s	user 0.002s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4790,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":18304,"update_count":450}
I20260812 06:19:18.740648  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling MajorDeltaCompactionOp(23e2936429da4ee79158aaadf5149d69): perf score=1.000000
I20260812 06:19:18.892760  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: MajorDeltaCompactionOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.152s	user 0.117s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631305,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1712,"lbm_read_time_us":10012,"lbm_reads_lt_1ms":468,"lbm_write_time_us":31836,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:19:18.893436  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=11.118625
I20260812 06:19:18.949465  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.056s	user 0.032s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":27438,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:19:18.950132  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=2.188937
I20260812 06:19:18.964897  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5161,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:18.965458  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling MajorDeltaCompactionOp(23e2936429da4ee79158aaadf5149d69): perf score=1.000000
I20260812 06:19:19.118083  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: MajorDeltaCompactionOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.152s	user 0.113s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":366,"lbm_read_time_us":9328,"lbm_reads_lt_1ms":472,"lbm_write_time_us":32288,"lbm_writes_lt_1ms":443,"mutex_wait_us":54,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":23040,"update_count":2000}
I20260812 06:19:19.118928  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=10.126437
I20260812 06:19:19.165977  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.047s	user 0.031s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":20058,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:19.166666  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=2.188937
I20260812 06:19:19.184733  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.018s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6613,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:19.185506  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushMRSOp(23e2936429da4ee79158aaadf5149d69): perf score=1.000000
I20260812 06:19:19.217162  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushMRSOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":304,"dirs.run_wall_time_us":1557,"drs_written":1,"lbm_read_time_us":117,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1935,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:19.218147  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling LogGCOp(23e2936429da4ee79158aaadf5149d69): free 120553592 bytes of WAL
I20260812 06:19:19.218415  9878 log_reader.cc:385] T 23e2936429da4ee79158aaadf5149d69: removed 12 log segments from log reader
I20260812 06:19:19.218462  9878 log.cc:1079] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/23e2936429da4ee79158aaadf5149d69/wal-000000028 (ops 132-136)
I20260812 06:19:19.218494  9878 log.cc:1079] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/23e2936429da4ee79158aaadf5149d69/wal-000000029 (ops 137-140)
I20260812 06:19:19.218569  9878 log.cc:1079] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/23e2936429da4ee79158aaadf5149d69/wal-000000030 (ops 141-145)
I20260812 06:19:19.218618  9878 log.cc:1079] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/23e2936429da4ee79158aaadf5149d69/wal-000000031 (ops 146-150)
I20260812 06:19:19.218691  9878 log.cc:1079] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/23e2936429da4ee79158aaadf5149d69/wal-000000032 (ops 151-154)
I20260812 06:19:19.218760  9878 log.cc:1079] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/23e2936429da4ee79158aaadf5149d69/wal-000000033 (ops 155-159)
I20260812 06:19:19.218804  9878 log.cc:1079] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/23e2936429da4ee79158aaadf5149d69/wal-000000034 (ops 160-164)
I20260812 06:19:19.218851  9878 log.cc:1079] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/23e2936429da4ee79158aaadf5149d69/wal-000000035 (ops 165-169)
I20260812 06:19:19.218895  9878 log.cc:1079] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/23e2936429da4ee79158aaadf5149d69/wal-000000036 (ops 170-174)
I20260812 06:19:19.218937  9878 log.cc:1079] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/23e2936429da4ee79158aaadf5149d69/wal-000000037 (ops 175-179)
I20260812 06:19:19.218981  9878 log.cc:1079] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/23e2936429da4ee79158aaadf5149d69/wal-000000038 (ops 180-184)
I20260812 06:19:19.219023  9878 log.cc:1079] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/23e2936429da4ee79158aaadf5149d69/wal-000000039 (ops 185-189)
I20260812 06:19:19.249382  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: LogGCOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.031s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:19:19.249979  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=3.181125
I20260812 06:19:19.266467  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.016s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":6629,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:19.267005  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling UndoDeltaBlockGCOp(23e2936429da4ee79158aaadf5149d69): 462 bytes on disk
I20260812 06:19:19.267483  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: UndoDeltaBlockGCOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:19:19.268121  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=2.188937
I20260812 06:19:19.279242  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4077,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:19.279767  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling MajorDeltaCompactionOp(23e2936429da4ee79158aaadf5149d69): perf score=1.000000
I20260812 06:19:19.470474  9759 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.487s	user 1.978s	sys 0.150s
I20260812 06:19:19.473433  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: MajorDeltaCompactionOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.193s	user 0.155s	sys 0.036s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836360,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1526,"lbm_read_time_us":13242,"lbm_reads_lt_1ms":674,"lbm_write_time_us":41717,"lbm_writes_lt_1ms":643,"mutex_wait_us":479,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":101,"threads_started":1,"update_count":3000}
I20260812 06:19:19.474231  9947 maintenance_manager.cc:419] P 4d729f24e43d4eef9097b068c63ca1cb: Scheduling FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69): perf score=14.095187
I20260812 06:19:19.508971  9759 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.038s	user 0.003s	sys 0.000s
I20260812 06:19:19.511188  9759 tablet_server.cc:179] TabletServer@127.9.135.193:0 shutting down...
I20260812 06:19:19.528710  9878 maintenance_manager.cc:643] P 4d729f24e43d4eef9097b068c63ca1cb: FlushDeltaMemStoresOp(23e2936429da4ee79158aaadf5149d69) complete. Timing: real 0.054s	user 0.031s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23969,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:19.529501  9759 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:19.529984  9759 tablet_replica.cc:333] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb: stopping tablet replica
I20260812 06:19:19.530498  9759 raft_consensus.cc:2243] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:19.530889  9759 raft_consensus.cc:2272] T 23e2936429da4ee79158aaadf5149d69 P 4d729f24e43d4eef9097b068c63ca1cb [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:19.547830  9759 tablet_server.cc:196] TabletServer@127.9.135.193:0 shutdown complete.
I20260812 06:19:19.555693  9759 master.cc:562] Master@127.9.135.254:45391 shutting down...
I20260812 06:19:19.560949  9759 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 40e160cc8d454b608b2f96fde903c5d5 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:19.561224  9759 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 40e160cc8d454b608b2f96fde903c5d5 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:19.561335  9759 tablet_replica.cc:333] T 00000000000000000000000000000000 P 40e160cc8d454b608b2f96fde903c5d5: stopping tablet replica
I20260812 06:19:19.574599  9759 master.cc:584] Master@127.9.135.254:45391 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (6049 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:19.677850  9759 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.9.135.254:39867
I20260812 06:19:19.678689  9759 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:19.683394  9986 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:19.683497  9987 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:19.683722  9759 server_base.cc:1061] running on GCE node
W20260812 06:19:19.683440  9989 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:19.684021  9759 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:19.684084  9759 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:19.684115  9759 hybrid_clock.cc:648] HybridClock initialized: now 1786515559684114 us; error 0 us; skew 500 ppm
I20260812 06:19:19.685465  9759 webserver.cc:533] Webserver started at http://127.9.135.254:36027/ using document root <none> and password file <none>
I20260812 06:19:19.685765  9759 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:19.685851  9759 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:19.685940  9759 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:19.686563  9759 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/master-0-root/instance:
uuid: "e86caddfaff74d48a13d2511e069209d"
format_stamp: "Formatted at 2026-08-12 06:19:19 on dist-test-slave-g350"
I20260812 06:19:19.689069  9759 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:19.690712  9997 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:19.691036  9759 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:19.691134  9759 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/master-0-root
uuid: "e86caddfaff74d48a13d2511e069209d"
format_stamp: "Formatted at 2026-08-12 06:19:19 on dist-test-slave-g350"
I20260812 06:19:19.691227  9759 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:19.719468  9759 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:19.720094  9759 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:19.726969  9759 rpc_server.cc:307] RPC server started. Bound to: 127.9.135.254:39867
I20260812 06:19:19.728235 10056 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.9.135.254:39867 every 8 connection(s)
I20260812 06:19:19.730619 10057 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:19.747853 10057 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e86caddfaff74d48a13d2511e069209d: Bootstrap starting.
I20260812 06:19:19.749151 10057 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P e86caddfaff74d48a13d2511e069209d: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:19.750639 10057 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e86caddfaff74d48a13d2511e069209d: No bootstrap required, opened a new log
I20260812 06:19:19.751142 10057 raft_consensus.cc:359] T 00000000000000000000000000000000 P e86caddfaff74d48a13d2511e069209d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e86caddfaff74d48a13d2511e069209d" member_type: VOTER }
I20260812 06:19:19.751497 10057 raft_consensus.cc:385] T 00000000000000000000000000000000 P e86caddfaff74d48a13d2511e069209d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:19.751547 10057 raft_consensus.cc:740] T 00000000000000000000000000000000 P e86caddfaff74d48a13d2511e069209d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e86caddfaff74d48a13d2511e069209d, State: Initialized, Role: FOLLOWER
I20260812 06:19:19.751725 10057 consensus_queue.cc:260] T 00000000000000000000000000000000 P e86caddfaff74d48a13d2511e069209d [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: "e86caddfaff74d48a13d2511e069209d" member_type: VOTER }
I20260812 06:19:19.751840 10057 raft_consensus.cc:399] T 00000000000000000000000000000000 P e86caddfaff74d48a13d2511e069209d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:19.751868 10057 raft_consensus.cc:493] T 00000000000000000000000000000000 P e86caddfaff74d48a13d2511e069209d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:19.751900 10057 raft_consensus.cc:3060] T 00000000000000000000000000000000 P e86caddfaff74d48a13d2511e069209d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:19.752714 10057 raft_consensus.cc:515] T 00000000000000000000000000000000 P e86caddfaff74d48a13d2511e069209d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e86caddfaff74d48a13d2511e069209d" member_type: VOTER }
I20260812 06:19:19.752856 10057 leader_election.cc:304] T 00000000000000000000000000000000 P e86caddfaff74d48a13d2511e069209d [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: e86caddfaff74d48a13d2511e069209d; no voters: 
I20260812 06:19:19.753053 10057 leader_election.cc:290] T 00000000000000000000000000000000 P e86caddfaff74d48a13d2511e069209d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:19.753391 10061 raft_consensus.cc:2804] T 00000000000000000000000000000000 P e86caddfaff74d48a13d2511e069209d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:19.753574 10061 raft_consensus.cc:697] T 00000000000000000000000000000000 P e86caddfaff74d48a13d2511e069209d [term 1 LEADER]: Becoming Leader. State: Replica: e86caddfaff74d48a13d2511e069209d, State: Running, Role: LEADER
I20260812 06:19:19.753717 10057 sys_catalog.cc:565] T 00000000000000000000000000000000 P e86caddfaff74d48a13d2511e069209d [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:19.753747 10061 consensus_queue.cc:237] T 00000000000000000000000000000000 P e86caddfaff74d48a13d2511e069209d [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: "e86caddfaff74d48a13d2511e069209d" member_type: VOTER }
I20260812 06:19:19.754262 10060 sys_catalog.cc:455] T 00000000000000000000000000000000 P e86caddfaff74d48a13d2511e069209d [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "e86caddfaff74d48a13d2511e069209d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e86caddfaff74d48a13d2511e069209d" member_type: VOTER } }
I20260812 06:19:19.754312 10062 sys_catalog.cc:455] T 00000000000000000000000000000000 P e86caddfaff74d48a13d2511e069209d [sys.catalog]: SysCatalogTable state changed. Reason: New leader e86caddfaff74d48a13d2511e069209d. Latest consensus state: current_term: 1 leader_uuid: "e86caddfaff74d48a13d2511e069209d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e86caddfaff74d48a13d2511e069209d" member_type: VOTER } }
I20260812 06:19:19.754369 10060 sys_catalog.cc:458] T 00000000000000000000000000000000 P e86caddfaff74d48a13d2511e069209d [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:19.754398 10062 sys_catalog.cc:458] T 00000000000000000000000000000000 P e86caddfaff74d48a13d2511e069209d [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:19.754734 10066 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:19.755610 10066 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:19.756484  9759 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:19.758438 10066 catalog_manager.cc:1383] Generated new cluster ID: 38e1572fc11348cfbb723cc31f86ba7a
I20260812 06:19:19.758637 10066 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:19.788282 10066 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:19.788941 10066 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:19.801986 10066 catalog_manager.cc:6092] T 00000000000000000000000000000000 P e86caddfaff74d48a13d2511e069209d: Generated new TSK 0
I20260812 06:19:19.802242 10066 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:19.822003  9759 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:19:19.824509  9759 server_base.cc:1061] running on GCE node
W20260812 06:19:19.824399 10082 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:19.824460 10084 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:19.824674 10081 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:19.825048  9759 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:19.825124  9759 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:19.825176  9759 hybrid_clock.cc:648] HybridClock initialized: now 1786515559825175 us; error 0 us; skew 500 ppm
I20260812 06:19:19.826301  9759 webserver.cc:533] Webserver started at http://127.9.135.193:35947/ using document root <none> and password file <none>
I20260812 06:19:19.826524  9759 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:19.826610  9759 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:19.826704  9759 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:19.827193  9759 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/instance:
uuid: "10a9c1c288684ec4958c66b3be0777d0"
format_stamp: "Formatted at 2026-08-12 06:19:19 on dist-test-slave-g350"
I20260812 06:19:19.829048  9759 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.001s	sys 0.001s
I20260812 06:19:19.830399 10089 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:19.830844  9759 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:19.830956  9759 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root
uuid: "10a9c1c288684ec4958c66b3be0777d0"
format_stamp: "Formatted at 2026-08-12 06:19:19 on dist-test-slave-g350"
I20260812 06:19:19.831068  9759 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:19.845922  9759 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:19.846415  9759 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:19.846809  9759 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:19.847386  9759 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:19.847458  9759 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:19.847527  9759 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:19.847584  9759 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:19.854792  9759 rpc_server.cc:307] RPC server started. Bound to: 127.9.135.193:35087
I20260812 06:19:19.854889 10164 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.9.135.193:35087 every 8 connection(s)
I20260812 06:19:19.861982 10165 heartbeater.cc:344] Connected to a master server at 127.9.135.254:39867
I20260812 06:19:19.862178 10165 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:19.862517 10165 heartbeater.cc:507] Master 127.9.135.254:39867 requested a full tablet report, sending...
I20260812 06:19:19.863457  9759 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.008188007s
I20260812 06:19:19.863456 10019 ts_manager.cc:194] Registered new tserver with Master: 10a9c1c288684ec4958c66b3be0777d0 (127.9.135.193:35087)
I20260812 06:19:19.864354 10019 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:59090
I20260812 06:19:19.872653 10019 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:59104:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:19.884399 10123 tablet_service.cc:1511] Processing CreateTablet for tablet 4063343323464faeaa012fd261aa250e (DEFAULT_TABLE table=heavy-update-compaction-test [id=6420c56e745a4087b913224f1104f069]), partition=
I20260812 06:19:19.884878 10123 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 4063343323464faeaa012fd261aa250e. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:19.887406 10177 tablet_bootstrap.cc:492] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Bootstrap starting.
I20260812 06:19:19.888545 10177 tablet_bootstrap.cc:654] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:19.890036 10177 tablet_bootstrap.cc:492] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: No bootstrap required, opened a new log
I20260812 06:19:19.890285 10177 ts_tablet_manager.cc:1403] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:19.890844 10177 raft_consensus.cc:359] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "10a9c1c288684ec4958c66b3be0777d0" member_type: VOTER last_known_addr { host: "127.9.135.193" port: 35087 } }
I20260812 06:19:19.890986 10177 raft_consensus.cc:385] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:19.891042 10177 raft_consensus.cc:740] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 10a9c1c288684ec4958c66b3be0777d0, State: Initialized, Role: FOLLOWER
I20260812 06:19:19.891259 10177 consensus_queue.cc:260] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0 [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: "10a9c1c288684ec4958c66b3be0777d0" member_type: VOTER last_known_addr { host: "127.9.135.193" port: 35087 } }
I20260812 06:19:19.891389 10177 raft_consensus.cc:399] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:19.891467 10177 raft_consensus.cc:493] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:19.891531 10177 raft_consensus.cc:3060] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:19.892480 10177 raft_consensus.cc:515] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "10a9c1c288684ec4958c66b3be0777d0" member_type: VOTER last_known_addr { host: "127.9.135.193" port: 35087 } }
I20260812 06:19:19.892660 10177 leader_election.cc:304] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0 [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: 10a9c1c288684ec4958c66b3be0777d0; no voters: 
I20260812 06:19:19.892943 10177 leader_election.cc:290] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:19.893447 10177 ts_tablet_manager.cc:1434] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Time spent starting tablet: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:19:19.893659 10179 raft_consensus.cc:2804] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:19.893760 10165 heartbeater.cc:499] Master 127.9.135.254:39867 was elected leader, sending a full tablet report...
I20260812 06:19:19.893775 10179 raft_consensus.cc:697] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0 [term 1 LEADER]: Becoming Leader. State: Replica: 10a9c1c288684ec4958c66b3be0777d0, State: Running, Role: LEADER
I20260812 06:19:19.893967 10179 consensus_queue.cc:237] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0 [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: "10a9c1c288684ec4958c66b3be0777d0" member_type: VOTER last_known_addr { host: "127.9.135.193" port: 35087 } }
I20260812 06:19:19.895529 10019 catalog_manager.cc:5719] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0 reported cstate change: term changed from 0 to 1, leader changed from <none> to 10a9c1c288684ec4958c66b3be0777d0 (127.9.135.193). New cstate: current_term: 1 leader_uuid: "10a9c1c288684ec4958c66b3be0777d0" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "10a9c1c288684ec4958c66b3be0777d0" member_type: VOTER last_known_addr { host: "127.9.135.193" port: 35087 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:19.962913  9759 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.062s	user 0.013s	sys 0.011s
I20260812 06:19:20.105983 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushMRSOp(4063343323464faeaa012fd261aa250e): perf score=15.086190
I20260812 06:19:20.267822 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushMRSOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.161s	user 0.107s	sys 0.048s Metrics: {"bytes_written":12307489,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":54,"dirs.run_cpu_time_us":242,"dirs.run_wall_time_us":1013,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42303,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"update_count":1500}
I20260812 06:19:20.268517 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling LogGCOp(4063343323464faeaa012fd261aa250e): free 11976772 bytes of WAL
I20260812 06:19:20.268751 10094 log_reader.cc:385] T 4063343323464faeaa012fd261aa250e: removed 1 log segments from log reader
I20260812 06:19:20.268795 10094 log.cc:1079] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/4063343323464faeaa012fd261aa250e/wal-000000001 (ops 1-6)
I20260812 06:19:20.271253 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: LogGCOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:20.271607 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=2.188937
I20260812 06:19:20.284762 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4772,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:20.285296 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling MajorDeltaCompactionOp(4063343323464faeaa012fd261aa250e): perf score=1.000000
I20260812 06:19:20.441430 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: MajorDeltaCompactionOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.156s	user 0.119s	sys 0.037s 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":735,"lbm_read_time_us":11671,"lbm_reads_lt_1ms":468,"lbm_write_time_us":28395,"lbm_writes_lt_1ms":443,"mutex_wait_us":3,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3200,"thread_start_us":378,"threads_started":5,"update_count":2000}
I20260812 06:19:20.442225 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling UndoDeltaBlockGCOp(4063343323464faeaa012fd261aa250e): 12308958 bytes on disk
I20260812 06:19:20.442806 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: UndoDeltaBlockGCOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:19:20.443557 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=10.126437
I20260812 06:19:20.484108 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.040s	user 0.026s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":18437,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:20.484665 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=2.188937
I20260812 06:19:20.496048 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4255,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:20.496847 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling MajorDeltaCompactionOp(4063343323464faeaa012fd261aa250e): perf score=1.000000
I20260812 06:19:20.673623 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: MajorDeltaCompactionOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.177s	user 0.117s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1333,"lbm_read_time_us":10555,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28796,"lbm_writes_lt_1ms":443,"mutex_wait_us":404,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2000}
I20260812 06:19:20.674422 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=11.118625
I20260812 06:19:20.721567 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.047s	user 0.025s	sys 0.015s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":18561,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:20.722188 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=2.188937
I20260812 06:19:20.735347 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.013s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4306,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:20.735931 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=2.188937
I20260812 06:19:20.766539 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.030s	user 0.009s	sys 0.020s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5991,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:20.767174 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling MajorDeltaCompactionOp(4063343323464faeaa012fd261aa250e): perf score=1.000000
I20260812 06:19:20.967690 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: MajorDeltaCompactionOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.200s	user 0.132s	sys 0.068s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733836,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":729,"lbm_read_time_us":12105,"lbm_reads_lt_1ms":573,"lbm_write_time_us":34905,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:19:20.968525 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=10.126437
I20260812 06:19:21.010874 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.042s	user 0.022s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16724,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:21.011677 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=2.188937
I20260812 06:19:21.024901 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4935,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:21.025502 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling MajorDeltaCompactionOp(4063343323464faeaa012fd261aa250e): perf score=1.000000
I20260812 06:19:21.161722 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: MajorDeltaCompactionOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.136s	user 0.095s	sys 0.040s 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":908,"lbm_read_time_us":9850,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24893,"lbm_writes_lt_1ms":443,"mutex_wait_us":376,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5120,"update_count":2000}
I20260812 06:19:21.162475 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=10.126437
I20260812 06:19:21.207391 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.045s	user 0.022s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15564,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:21.207921 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=2.188937
I20260812 06:19:21.221390 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.013s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4438,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:21.222077 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling MajorDeltaCompactionOp(4063343323464faeaa012fd261aa250e): perf score=1.000000
I20260812 06:19:21.351032 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: MajorDeltaCompactionOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.129s	user 0.100s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1036,"lbm_read_time_us":8313,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24261,"lbm_writes_lt_1ms":443,"mutex_wait_us":394,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":20608,"update_count":2000}
I20260812 06:19:21.351944 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=10.126437
I20260812 06:19:21.402931 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.051s	user 0.022s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15338,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:21.403607 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=2.188937
I20260812 06:19:21.416474 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4682,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:21.417305 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling MajorDeltaCompactionOp(4063343323464faeaa012fd261aa250e): perf score=1.000000
I20260812 06:19:21.552734 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: MajorDeltaCompactionOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.135s	user 0.107s	sys 0.028s 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":1871,"lbm_read_time_us":10636,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24737,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":34688,"update_count":2000}
I20260812 06:19:21.553977 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=10.126437
I20260812 06:19:21.612826 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.059s	user 0.028s	sys 0.024s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":20159,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:21.613524 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=2.188937
I20260812 06:19:21.626048 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4681,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:21.626564 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushMRSOp(4063343323464faeaa012fd261aa250e): perf score=1.000000
I20260812 06:19:21.671576 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushMRSOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.045s	user 0.035s	sys 0.000s Metrics: {"bytes_written":1193504,"cfile_init":1,"dirs.queue_time_us":107,"dirs.run_cpu_time_us":320,"dirs.run_wall_time_us":1629,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1690,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:21.672429 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling LogGCOp(4063343323464faeaa012fd261aa250e): free 116849504 bytes of WAL
I20260812 06:19:21.672709 10094 log_reader.cc:385] T 4063343323464faeaa012fd261aa250e: removed 12 log segments from log reader
I20260812 06:19:21.672756 10094 log.cc:1079] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/4063343323464faeaa012fd261aa250e/wal-000000002 (ops 7-11)
I20260812 06:19:21.672787 10094 log.cc:1079] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/4063343323464faeaa012fd261aa250e/wal-000000003 (ops 12-16)
I20260812 06:19:21.672855 10094 log.cc:1079] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/4063343323464faeaa012fd261aa250e/wal-000000004 (ops 17-20)
I20260812 06:19:21.672890 10094 log.cc:1079] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/4063343323464faeaa012fd261aa250e/wal-000000005 (ops 21-25)
I20260812 06:19:21.672931 10094 log.cc:1079] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/4063343323464faeaa012fd261aa250e/wal-000000006 (ops 26-30)
I20260812 06:19:21.672991 10094 log.cc:1079] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/4063343323464faeaa012fd261aa250e/wal-000000007 (ops 31-35)
I20260812 06:19:21.673031 10094 log.cc:1079] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/4063343323464faeaa012fd261aa250e/wal-000000008 (ops 36-40)
I20260812 06:19:21.673074 10094 log.cc:1079] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/4063343323464faeaa012fd261aa250e/wal-000000009 (ops 41-44)
I20260812 06:19:21.673113 10094 log.cc:1079] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/4063343323464faeaa012fd261aa250e/wal-000000010 (ops 45-49)
I20260812 06:19:21.673177 10094 log.cc:1079] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/4063343323464faeaa012fd261aa250e/wal-000000011 (ops 50-54)
I20260812 06:19:21.673223 10094 log.cc:1079] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/4063343323464faeaa012fd261aa250e/wal-000000012 (ops 55-58)
I20260812 06:19:21.673261 10094 log.cc:1079] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/4063343323464faeaa012fd261aa250e/wal-000000013 (ops 59-63)
I20260812 06:19:21.700261 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: LogGCOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.028s	user 0.002s	sys 0.023s Metrics: {}
I20260812 06:19:21.700810 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling UndoDeltaBlockGCOp(4063343323464faeaa012fd261aa250e): 461 bytes on disk
I20260812 06:19:21.701468 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: UndoDeltaBlockGCOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:19:21.702056 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=3.181125
I20260812 06:19:21.718654 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.016s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4732,"lbm_writes_lt_1ms":113,"mutex_wait_us":2,"reinsert_count":0,"update_count":550}
I20260812 06:19:21.719228 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=2.188937
I20260812 06:19:21.732920 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.013s	user 0.000s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5215,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:21.733520 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling MajorDeltaCompactionOp(4063343323464faeaa012fd261aa250e): perf score=1.000000
I20260812 06:19:21.969837 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: MajorDeltaCompactionOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.236s	user 0.168s	sys 0.068s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836363,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":272,"lbm_read_time_us":15489,"lbm_reads_lt_1ms":674,"lbm_write_time_us":37894,"lbm_writes_lt_1ms":643,"mutex_wait_us":40,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":25472,"thread_start_us":76,"threads_started":1,"update_count":3000}
I20260812 06:19:21.970510 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=14.095187
I20260812 06:19:22.035708 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.064s	user 0.034s	sys 0.028s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":29449,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":2000}
I20260812 06:19:22.036443 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling MajorDeltaCompactionOp(4063343323464faeaa012fd261aa250e): perf score=1.000000
I20260812 06:19:22.218703 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: MajorDeltaCompactionOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.182s	user 0.117s	sys 0.051s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631191,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":864,"lbm_read_time_us":10429,"lbm_reads_lt_1ms":463,"lbm_write_time_us":29607,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:19:22.219645 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=14.095187
I20260812 06:19:22.273095 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.053s	user 0.028s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22704,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:22.273803 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=2.188937
I20260812 06:19:22.288069 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.014s	user 0.002s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4761,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:22.288542 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling MajorDeltaCompactionOp(4063343323464faeaa012fd261aa250e): perf score=1.000000
I20260812 06:19:22.486240 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: MajorDeltaCompactionOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.198s	user 0.134s	sys 0.058s 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":321,"lbm_read_time_us":11474,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31887,"lbm_writes_lt_1ms":543,"mutex_wait_us":62,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12288,"update_count":2500}
I20260812 06:19:22.487036 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=14.095187
I20260812 06:19:22.541188 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.054s	user 0.037s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22329,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:22.541826 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=2.188937
I20260812 06:19:22.554899 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.013s	user 0.003s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4721,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:22.556484 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling MajorDeltaCompactionOp(4063343323464faeaa012fd261aa250e): perf score=1.000000
I20260812 06:19:22.730692 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: MajorDeltaCompactionOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.174s	user 0.130s	sys 0.035s 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":187,"lbm_read_time_us":10563,"lbm_reads_lt_1ms":568,"lbm_write_time_us":32949,"lbm_writes_lt_1ms":543,"mutex_wait_us":45,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2500}
I20260812 06:19:22.731525 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=14.095187
I20260812 06:19:22.790701 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.059s	user 0.021s	sys 0.028s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":22473,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:22.791559 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=2.188937
I20260812 06:19:22.803236 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4354,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:22.804004 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling MajorDeltaCompactionOp(4063343323464faeaa012fd261aa250e): perf score=1.000000
I20260812 06:19:22.970810 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: MajorDeltaCompactionOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.167s	user 0.127s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733726,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1510,"lbm_read_time_us":9246,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35721,"lbm_writes_lt_1ms":543,"mutex_wait_us":459,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:19:22.971796 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=11.118625
I20260812 06:19:23.018383 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.046s	user 0.033s	sys 0.012s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":20335,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:19:23.018946 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=2.188937
I20260812 06:19:23.041589 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.022s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6153,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:23.042114 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=2.188937
I20260812 06:19:23.053751 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.011s	user 0.010s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3758,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:23.054315 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling MajorDeltaCompactionOp(4063343323464faeaa012fd261aa250e): perf score=1.000000
I20260812 06:19:23.206348 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: MajorDeltaCompactionOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.152s	user 0.102s	sys 0.049s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733836,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":725,"lbm_read_time_us":9891,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31136,"lbm_writes_lt_1ms":543,"mutex_wait_us":382,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:19:23.207170 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=10.126437
I20260812 06:19:23.246694 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.039s	user 0.021s	sys 0.016s Metrics: {"bytes_written":12348514,"delete_count":0,"lbm_write_time_us":16440,"lbm_writes_lt_1ms":304,"reinsert_count":0,"update_count":1505}
I20260812 06:19:23.247352 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=2.188937
I20260812 06:19:23.259109 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4061634,"delete_count":0,"lbm_write_time_us":4531,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":495}
I20260812 06:19:23.259646 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushMRSOp(4063343323464faeaa012fd261aa250e): perf score=1.000000
I20260812 06:19:23.292099 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushMRSOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.032s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":110,"dirs.run_cpu_time_us":238,"dirs.run_wall_time_us":1678,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1573,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:23.292843 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling LogGCOp(4063343323464faeaa012fd261aa250e): free 128867446 bytes of WAL
I20260812 06:19:23.293100 10094 log_reader.cc:385] T 4063343323464faeaa012fd261aa250e: removed 13 log segments from log reader
I20260812 06:19:23.293149 10094 log.cc:1079] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/4063343323464faeaa012fd261aa250e/wal-000000014 (ops 64-68)
I20260812 06:19:23.293217 10094 log.cc:1079] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/4063343323464faeaa012fd261aa250e/wal-000000015 (ops 69-72)
I20260812 06:19:23.293267 10094 log.cc:1079] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/4063343323464faeaa012fd261aa250e/wal-000000016 (ops 73-77)
I20260812 06:19:23.293318 10094 log.cc:1079] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/4063343323464faeaa012fd261aa250e/wal-000000017 (ops 78-82)
I20260812 06:19:23.293372 10094 log.cc:1079] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/4063343323464faeaa012fd261aa250e/wal-000000018 (ops 83-87)
I20260812 06:19:23.293442 10094 log.cc:1079] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/4063343323464faeaa012fd261aa250e/wal-000000019 (ops 88-92)
I20260812 06:19:23.293490 10094 log.cc:1079] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/4063343323464faeaa012fd261aa250e/wal-000000020 (ops 93-97)
I20260812 06:19:23.293534 10094 log.cc:1079] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/4063343323464faeaa012fd261aa250e/wal-000000021 (ops 98-102)
I20260812 06:19:23.293578 10094 log.cc:1079] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/4063343323464faeaa012fd261aa250e/wal-000000022 (ops 103-106)
I20260812 06:19:23.293661 10094 log.cc:1079] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/4063343323464faeaa012fd261aa250e/wal-000000023 (ops 107-111)
I20260812 06:19:23.293709 10094 log.cc:1079] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/4063343323464faeaa012fd261aa250e/wal-000000024 (ops 112-116)
I20260812 06:19:23.293751 10094 log.cc:1079] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/4063343323464faeaa012fd261aa250e/wal-000000025 (ops 117-120)
I20260812 06:19:23.293793 10094 log.cc:1079] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/4063343323464faeaa012fd261aa250e/wal-000000026 (ops 121-125)
I20260812 06:19:23.327520 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: LogGCOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.034s	user 0.002s	sys 0.030s Metrics: {}
I20260812 06:19:23.328323 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling UndoDeltaBlockGCOp(4063343323464faeaa012fd261aa250e): 473 bytes on disk
I20260812 06:19:23.329066 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: UndoDeltaBlockGCOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":82,"lbm_reads_lt_1ms":4}
I20260812 06:19:23.329820 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=3.181125
I20260812 06:19:23.342698 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":5072,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:23.343191 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=2.188937
I20260812 06:19:23.353564 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3925,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:23.354336 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling MajorDeltaCompactionOp(4063343323464faeaa012fd261aa250e): perf score=1.000000
I20260812 06:19:23.540325 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: MajorDeltaCompactionOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.186s	user 0.140s	sys 0.042s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836360,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":725,"lbm_read_time_us":12008,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36122,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":22144,"thread_start_us":87,"threads_started":1,"update_count":3000}
I20260812 06:19:23.541049 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=14.095187
I20260812 06:19:23.607820 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.066s	user 0.036s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":29444,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:23.608426 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=2.188937
I20260812 06:19:23.621202 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.013s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4234,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:23.621810 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling MajorDeltaCompactionOp(4063343323464faeaa012fd261aa250e): perf score=1.000000
I20260812 06:19:23.795130 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: MajorDeltaCompactionOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.173s	user 0.126s	sys 0.041s 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":610,"lbm_read_time_us":9797,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34997,"lbm_writes_lt_1ms":543,"mutex_wait_us":329,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":2500}
I20260812 06:19:23.795821 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=12.110812
I20260812 06:19:23.837843 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.042s	user 0.022s	sys 0.019s Metrics: {"bytes_written":13497199,"delete_count":0,"lbm_write_time_us":18375,"lbm_writes_lt_1ms":332,"reinsert_count":0,"update_count":1645}
I20260812 06:19:23.838495 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=1.196750
I20260812 06:19:23.857259 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.019s	user 0.006s	sys 0.005s Metrics: {"bytes_written":2912930,"delete_count":0,"lbm_write_time_us":4637,"lbm_writes_lt_1ms":74,"reinsert_count":0,"update_count":355}
I20260812 06:19:23.858234 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling MajorDeltaCompactionOp(4063343323464faeaa012fd261aa250e): perf score=1.000000
I20260812 06:19:24.035518 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: MajorDeltaCompactionOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.177s	user 0.132s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631292,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1444,"lbm_read_time_us":12445,"lbm_reads_lt_1ms":464,"lbm_write_time_us":28130,"lbm_writes_lt_1ms":443,"mutex_wait_us":53,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":384,"update_count":2000}
I20260812 06:19:24.036255 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=14.095187
I20260812 06:19:24.102169 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.066s	user 0.024s	sys 0.036s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":28049,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:24.102751 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=2.188937
I20260812 06:19:24.127750 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.025s	user 0.011s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6091,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:24.128702 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling MajorDeltaCompactionOp(4063343323464faeaa012fd261aa250e): perf score=1.000000
I20260812 06:19:24.337661 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: MajorDeltaCompactionOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.209s	user 0.161s	sys 0.047s 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":1413,"lbm_read_time_us":15432,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33521,"lbm_writes_lt_1ms":543,"mutex_wait_us":341,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":41344,"update_count":2500}
I20260812 06:19:24.338570 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=14.095187
I20260812 06:19:24.394160 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.055s	user 0.032s	sys 0.020s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":23832,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:24.394757 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=2.188937
I20260812 06:19:24.407251 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4532,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:24.407810 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling MajorDeltaCompactionOp(4063343323464faeaa012fd261aa250e): perf score=1.000000
I20260812 06:19:24.593830 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: MajorDeltaCompactionOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.186s	user 0.115s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":379,"lbm_read_time_us":11639,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29283,"lbm_writes_lt_1ms":543,"mutex_wait_us":77,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":2500}
I20260812 06:19:24.594468 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=14.095187
I20260812 06:19:24.659770 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.065s	user 0.034s	sys 0.017s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23989,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:24.660362 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=2.188937
I20260812 06:19:24.673461 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.013s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4561,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:24.674099 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling MajorDeltaCompactionOp(4063343323464faeaa012fd261aa250e): perf score=1.000000
I20260812 06:19:24.831049 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: MajorDeltaCompactionOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.157s	user 0.112s	sys 0.044s 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":485,"lbm_read_time_us":11993,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32560,"lbm_writes_lt_1ms":543,"mutex_wait_us":58,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20992,"update_count":2500}
I20260812 06:19:24.832001 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=10.126437
I20260812 06:19:24.875602 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.043s	user 0.022s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17715,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:24.876896 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=2.188937
I20260812 06:19:24.905206 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.028s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5713,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:24.905900 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=2.188937
I20260812 06:19:24.918437 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.012s	user 0.003s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4739,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:24.918962 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushMRSOp(4063343323464faeaa012fd261aa250e): perf score=1.000000
I20260812 06:19:24.954597 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushMRSOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.035s	user 0.034s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":51,"dirs.run_cpu_time_us":244,"dirs.run_wall_time_us":1398,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2492,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:24.955582 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling LogGCOp(4063343323464faeaa012fd261aa250e): free 129320779 bytes of WAL
I20260812 06:19:24.955955 10094 log_reader.cc:385] T 4063343323464faeaa012fd261aa250e: removed 13 log segments from log reader
I20260812 06:19:24.956027 10094 log.cc:1079] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/4063343323464faeaa012fd261aa250e/wal-000000027 (ops 126-130)
I20260812 06:19:24.956086 10094 log.cc:1079] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/4063343323464faeaa012fd261aa250e/wal-000000028 (ops 131-134)
I20260812 06:19:24.956138 10094 log.cc:1079] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/4063343323464faeaa012fd261aa250e/wal-000000029 (ops 135-139)
I20260812 06:19:24.956182 10094 log.cc:1079] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/4063343323464faeaa012fd261aa250e/wal-000000030 (ops 140-144)
I20260812 06:19:24.956219 10094 log.cc:1079] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/4063343323464faeaa012fd261aa250e/wal-000000031 (ops 145-148)
I20260812 06:19:24.956259 10094 log.cc:1079] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/4063343323464faeaa012fd261aa250e/wal-000000032 (ops 149-153)
I20260812 06:19:24.956297 10094 log.cc:1079] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/4063343323464faeaa012fd261aa250e/wal-000000033 (ops 154-158)
I20260812 06:19:24.956336 10094 log.cc:1079] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/4063343323464faeaa012fd261aa250e/wal-000000034 (ops 159-163)
I20260812 06:19:24.956375 10094 log.cc:1079] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/4063343323464faeaa012fd261aa250e/wal-000000035 (ops 164-168)
I20260812 06:19:24.956413 10094 log.cc:1079] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/4063343323464faeaa012fd261aa250e/wal-000000036 (ops 169-173)
I20260812 06:19:24.956454 10094 log.cc:1079] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/4063343323464faeaa012fd261aa250e/wal-000000037 (ops 174-178)
I20260812 06:19:24.956494 10094 log.cc:1079] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/4063343323464faeaa012fd261aa250e/wal-000000038 (ops 179-183)
I20260812 06:19:24.956532 10094 log.cc:1079] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: Deleting log segment in path: /tmp/dist-test-taskFna6pn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553616536-9759-0/minicluster-data/ts-0-root/wals/4063343323464faeaa012fd261aa250e/wal-000000039 (ops 184-188)
I20260812 06:19:24.986922 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: LogGCOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.031s	user 0.003s	sys 0.027s Metrics: {}
I20260812 06:19:24.987564 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling UndoDeltaBlockGCOp(4063343323464faeaa012fd261aa250e): 483 bytes on disk
I20260812 06:19:24.988111 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: UndoDeltaBlockGCOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:19:24.988917 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=3.181125
I20260812 06:19:25.001579 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":5033,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:25.002310 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=2.188937
I20260812 06:19:25.026238 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.024s	user 0.012s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4091,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:25.026881 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling MajorDeltaCompactionOp(4063343323464faeaa012fd261aa250e): perf score=1.000000
I20260812 06:19:25.291868  9759 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.329s	user 1.969s	sys 0.176s
I20260812 06:19:25.294696 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: MajorDeltaCompactionOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.268s	user 0.172s	sys 0.088s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32938892,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":317,"lbm_read_time_us":19442,"lbm_reads_lt_1ms":775,"lbm_write_time_us":42479,"lbm_writes_lt_1ms":743,"mutex_wait_us":32,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":16128,"thread_start_us":80,"threads_started":1,"update_count":3500}
I20260812 06:19:25.295497 10166 maintenance_manager.cc:419] P 10a9c1c288684ec4958c66b3be0777d0: Scheduling FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e): perf score=18.063937
I20260812 06:19:25.325112  9759 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.033s	user 0.001s	sys 0.000s
I20260812 06:19:25.325762  9759 tablet_server.cc:179] TabletServer@127.9.135.193:0 shutting down...
I20260812 06:19:25.372309 10094 maintenance_manager.cc:643] P 10a9c1c288684ec4958c66b3be0777d0: FlushDeltaMemStoresOp(4063343323464faeaa012fd261aa250e) complete. Timing: real 0.076s	user 0.054s	sys 0.019s Metrics: {"bytes_written":20512312,"delete_count":0,"lbm_write_time_us":29541,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:25.373026  9759 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:25.373291  9759 tablet_replica.cc:333] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0: stopping tablet replica
I20260812 06:19:25.373504  9759 raft_consensus.cc:2243] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:25.373723  9759 raft_consensus.cc:2272] T 4063343323464faeaa012fd261aa250e P 10a9c1c288684ec4958c66b3be0777d0 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:25.387955  9759 tablet_server.cc:196] TabletServer@127.9.135.193:0 shutdown complete.
I20260812 06:19:25.391587  9759 master.cc:562] Master@127.9.135.254:39867 shutting down...
I20260812 06:19:25.395725  9759 raft_consensus.cc:2243] T 00000000000000000000000000000000 P e86caddfaff74d48a13d2511e069209d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:25.395936  9759 raft_consensus.cc:2272] T 00000000000000000000000000000000 P e86caddfaff74d48a13d2511e069209d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:25.395985  9759 tablet_replica.cc:333] T 00000000000000000000000000000000 P e86caddfaff74d48a13d2511e069209d: stopping tablet replica
I20260812 06:19:25.409058  9759 master.cc:584] Master@127.9.135.254:39867 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5821 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11872 ms total)

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