[==========] 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:30.831658  8204 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.8.3.62:34893
I20260812 06:19:30.832810  8204 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:30.833467  8204 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:30.840468  8211 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:30.840613  8204 server_base.cc:1061] running on GCE node
W20260812 06:19:30.840613  8213 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:30.840849  8209 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:30.841375  8204 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:30.841495  8204 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:30.841578  8204 hybrid_clock.cc:648] HybridClock initialized: now 1786515570841575 us; error 0 us; skew 500 ppm
I20260812 06:19:30.843426  8204 webserver.cc:533] Webserver started at http://127.8.3.62:46093/ using document root <none> and password file <none>
I20260812 06:19:30.844008  8204 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:30.844095  8204 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:30.844368  8204 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:30.846112  8204 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/master-0-root/instance:
uuid: "571edc7984e44d5e9cac71b24a8a305e"
format_stamp: "Formatted at 2026-08-12 06:19:30 on dist-test-slave-cbsf"
I20260812 06:19:30.849747  8204 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.000s	sys 0.004s
I20260812 06:19:30.851841  8219 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:30.852932  8204 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.001s
I20260812 06:19:30.853091  8204 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/master-0-root
uuid: "571edc7984e44d5e9cac71b24a8a305e"
format_stamp: "Formatted at 2026-08-12 06:19:30 on dist-test-slave-cbsf"
I20260812 06:19:30.853188  8204 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-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:30.873168  8204 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:30.873900  8204 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:30.874104  8204 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:30.884181  8204 rpc_server.cc:307] RPC server started. Bound to: 127.8.3.62:34893
I20260812 06:19:30.884191  8282 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.3.62:34893 every 8 connection(s)
I20260812 06:19:30.886818  8283 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:30.892838  8283 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 571edc7984e44d5e9cac71b24a8a305e: Bootstrap starting.
I20260812 06:19:30.895460  8283 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 571edc7984e44d5e9cac71b24a8a305e: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:30.896485  8283 log.cc:826] T 00000000000000000000000000000000 P 571edc7984e44d5e9cac71b24a8a305e: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:30.898528  8283 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 571edc7984e44d5e9cac71b24a8a305e: No bootstrap required, opened a new log
I20260812 06:19:30.902880  8283 raft_consensus.cc:359] T 00000000000000000000000000000000 P 571edc7984e44d5e9cac71b24a8a305e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "571edc7984e44d5e9cac71b24a8a305e" member_type: VOTER }
I20260812 06:19:30.903092  8283 raft_consensus.cc:385] T 00000000000000000000000000000000 P 571edc7984e44d5e9cac71b24a8a305e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:30.903196  8283 raft_consensus.cc:740] T 00000000000000000000000000000000 P 571edc7984e44d5e9cac71b24a8a305e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 571edc7984e44d5e9cac71b24a8a305e, State: Initialized, Role: FOLLOWER
I20260812 06:19:30.903867  8283 consensus_queue.cc:260] T 00000000000000000000000000000000 P 571edc7984e44d5e9cac71b24a8a305e [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: "571edc7984e44d5e9cac71b24a8a305e" member_type: VOTER }
I20260812 06:19:30.904047  8283 raft_consensus.cc:399] T 00000000000000000000000000000000 P 571edc7984e44d5e9cac71b24a8a305e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:30.904134  8283 raft_consensus.cc:493] T 00000000000000000000000000000000 P 571edc7984e44d5e9cac71b24a8a305e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:30.904276  8283 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 571edc7984e44d5e9cac71b24a8a305e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:30.905256  8283 raft_consensus.cc:515] T 00000000000000000000000000000000 P 571edc7984e44d5e9cac71b24a8a305e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "571edc7984e44d5e9cac71b24a8a305e" member_type: VOTER }
I20260812 06:19:30.905750  8283 leader_election.cc:304] T 00000000000000000000000000000000 P 571edc7984e44d5e9cac71b24a8a305e [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: 571edc7984e44d5e9cac71b24a8a305e; no voters: 
I20260812 06:19:30.906126  8283 leader_election.cc:290] T 00000000000000000000000000000000 P 571edc7984e44d5e9cac71b24a8a305e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:30.906312  8287 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 571edc7984e44d5e9cac71b24a8a305e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:30.906595  8287 raft_consensus.cc:697] T 00000000000000000000000000000000 P 571edc7984e44d5e9cac71b24a8a305e [term 1 LEADER]: Becoming Leader. State: Replica: 571edc7984e44d5e9cac71b24a8a305e, State: Running, Role: LEADER
I20260812 06:19:30.907070  8287 consensus_queue.cc:237] T 00000000000000000000000000000000 P 571edc7984e44d5e9cac71b24a8a305e [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: "571edc7984e44d5e9cac71b24a8a305e" member_type: VOTER }
I20260812 06:19:30.907294  8283 sys_catalog.cc:565] T 00000000000000000000000000000000 P 571edc7984e44d5e9cac71b24a8a305e [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:30.909092  8288 sys_catalog.cc:455] T 00000000000000000000000000000000 P 571edc7984e44d5e9cac71b24a8a305e [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "571edc7984e44d5e9cac71b24a8a305e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "571edc7984e44d5e9cac71b24a8a305e" member_type: VOTER } }
I20260812 06:19:30.909144  8289 sys_catalog.cc:455] T 00000000000000000000000000000000 P 571edc7984e44d5e9cac71b24a8a305e [sys.catalog]: SysCatalogTable state changed. Reason: New leader 571edc7984e44d5e9cac71b24a8a305e. Latest consensus state: current_term: 1 leader_uuid: "571edc7984e44d5e9cac71b24a8a305e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "571edc7984e44d5e9cac71b24a8a305e" member_type: VOTER } }
I20260812 06:19:30.909231  8288 sys_catalog.cc:458] T 00000000000000000000000000000000 P 571edc7984e44d5e9cac71b24a8a305e [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:30.909261  8289 sys_catalog.cc:458] T 00000000000000000000000000000000 P 571edc7984e44d5e9cac71b24a8a305e [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:30.909950  8204 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:19:30.912037  8304 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 571edc7984e44d5e9cac71b24a8a305e: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:19:30.912106  8304 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:19:30.912197  8299 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:30.913095  8299 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:30.918509  8299 catalog_manager.cc:1383] Generated new cluster ID: a4e9bcddf24b4886bc3d7ba88e805132
I20260812 06:19:30.918594  8299 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:30.936821  8299 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:30.938112  8299 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:30.956388  8299 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 571edc7984e44d5e9cac71b24a8a305e: Generated new TSK 0
I20260812 06:19:30.957353  8299 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:30.975085  8204 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:30.978757  8311 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:30.978777  8310 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:30.978878  8313 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:30.979100  8204 server_base.cc:1061] running on GCE node
I20260812 06:19:30.979305  8204 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:30.979346  8204 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:30.979363  8204 hybrid_clock.cc:648] HybridClock initialized: now 1786515570979363 us; error 0 us; skew 500 ppm
I20260812 06:19:30.980429  8204 webserver.cc:533] Webserver started at http://127.8.3.1:36551/ using document root <none> and password file <none>
I20260812 06:19:30.980643  8204 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:30.980739  8204 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:30.980836  8204 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:30.981281  8204 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root/instance:
uuid: "9ae4771bd9214aa7a946edca370859de"
format_stamp: "Formatted at 2026-08-12 06:19:30 on dist-test-slave-cbsf"
I20260812 06:19:30.982940  8204 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:30.984016  8319 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:30.984280  8204 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:30.984359  8204 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root
uuid: "9ae4771bd9214aa7a946edca370859de"
format_stamp: "Formatted at 2026-08-12 06:19:30 on dist-test-slave-cbsf"
I20260812 06:19:30.984453  8204 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-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:31.008298  8204 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:31.008949  8204 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:31.009546  8204 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:31.010542  8204 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:31.010597  8204 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:31.010689  8204 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:31.010726  8204 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:31.017999  8204 rpc_server.cc:307] RPC server started. Bound to: 127.8.3.1:43589
I20260812 06:19:31.018030  8393 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.3.1:43589 every 8 connection(s)
I20260812 06:19:31.028990  8396 heartbeater.cc:344] Connected to a master server at 127.8.3.62:34893
I20260812 06:19:31.029284  8396 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:31.029781  8396 heartbeater.cc:507] Master 127.8.3.62:34893 requested a full tablet report, sending...
I20260812 06:19:31.031301  8238 ts_manager.cc:194] Registered new tserver with Master: 9ae4771bd9214aa7a946edca370859de (127.8.3.1:43589)
I20260812 06:19:31.032155  8204 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013415845s
I20260812 06:19:31.032559  8238 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:47484
I20260812 06:19:31.042364  8238 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:47498:
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:31.057018  8352 tablet_service.cc:1511] Processing CreateTablet for tablet 9a780e82a3a943ba83ea3a41c4030a4a (DEFAULT_TABLE table=heavy-update-compaction-test [id=29e3bf1710f94db1bc8a19261a8a2685]), partition=
I20260812 06:19:31.057615  8352 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 9a780e82a3a943ba83ea3a41c4030a4a. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:31.060415  8410 tablet_bootstrap.cc:492] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Bootstrap starting.
I20260812 06:19:31.061439  8410 tablet_bootstrap.cc:654] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:31.063058  8410 tablet_bootstrap.cc:492] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: No bootstrap required, opened a new log
I20260812 06:19:31.063212  8410 ts_tablet_manager.cc:1403] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:31.063702  8410 raft_consensus.cc:359] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9ae4771bd9214aa7a946edca370859de" member_type: VOTER last_known_addr { host: "127.8.3.1" port: 43589 } }
I20260812 06:19:31.063846  8410 raft_consensus.cc:385] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:31.063922  8410 raft_consensus.cc:740] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 9ae4771bd9214aa7a946edca370859de, State: Initialized, Role: FOLLOWER
I20260812 06:19:31.064090  8410 consensus_queue.cc:260] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de [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: "9ae4771bd9214aa7a946edca370859de" member_type: VOTER last_known_addr { host: "127.8.3.1" port: 43589 } }
I20260812 06:19:31.064204  8410 raft_consensus.cc:399] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:31.064257  8410 raft_consensus.cc:493] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:31.064316  8410 raft_consensus.cc:3060] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:31.065295  8410 raft_consensus.cc:515] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9ae4771bd9214aa7a946edca370859de" member_type: VOTER last_known_addr { host: "127.8.3.1" port: 43589 } }
I20260812 06:19:31.065426  8410 leader_election.cc:304] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de [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: 9ae4771bd9214aa7a946edca370859de; no voters: 
I20260812 06:19:31.065702  8410 leader_election.cc:290] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:31.065860  8412 raft_consensus.cc:2804] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:31.066090  8412 raft_consensus.cc:697] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de [term 1 LEADER]: Becoming Leader. State: Replica: 9ae4771bd9214aa7a946edca370859de, State: Running, Role: LEADER
I20260812 06:19:31.066128  8410 ts_tablet_manager.cc:1434] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:31.066243  8412 consensus_queue.cc:237] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de [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: "9ae4771bd9214aa7a946edca370859de" member_type: VOTER last_known_addr { host: "127.8.3.1" port: 43589 } }
I20260812 06:19:31.066444  8396 heartbeater.cc:499] Master 127.8.3.62:34893 was elected leader, sending a full tablet report...
I20260812 06:19:31.069244  8238 catalog_manager.cc:5719] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de reported cstate change: term changed from 0 to 1, leader changed from <none> to 9ae4771bd9214aa7a946edca370859de (127.8.3.1). New cstate: current_term: 1 leader_uuid: "9ae4771bd9214aa7a946edca370859de" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9ae4771bd9214aa7a946edca370859de" member_type: VOTER last_known_addr { host: "127.8.3.1" port: 43589 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:31.147588  8204 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.068s	user 0.023s	sys 0.012s
I20260812 06:19:31.269299  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushMRSOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=15.086190
I20260812 06:19:31.414837  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushMRSOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.145s	user 0.099s	sys 0.041s Metrics: {"bytes_written":8615323,"cfile_init":1,"compiler_manager_pool.queue_time_us":507,"delete_count":0,"dirs.queue_time_us":42,"dirs.run_cpu_time_us":248,"dirs.run_wall_time_us":1031,"drs_written":1,"lbm_read_time_us":94,"lbm_reads_lt_1ms":4,"lbm_write_time_us":34394,"lbm_writes_lt_1ms":567,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"thread_start_us":143,"threads_started":1,"update_count":1050}
I20260812 06:19:31.416046  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling LogGCOp(9a780e82a3a943ba83ea3a41c4030a4a): free 11976772 bytes of WAL
I20260812 06:19:31.416389  8325 log_reader.cc:385] T 9a780e82a3a943ba83ea3a41c4030a4a: removed 1 log segments from log reader
I20260812 06:19:31.416460  8325 log.cc:1079] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/9a780e82a3a943ba83ea3a41c4030a4a/wal-000000001 (ops 1-6)
I20260812 06:19:31.420054  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: LogGCOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.004s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:31.420451  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=2.188937
I20260812 06:19:31.437294  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.017s	user 0.009s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6361,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:31.438333  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=1.000000
I20260812 06:19:31.557067  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.119s	user 0.083s	sys 0.033s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528891,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":764,"lbm_read_time_us":7098,"lbm_reads_lt_1ms":364,"lbm_write_time_us":22948,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":4224,"thread_start_us":355,"threads_started":5,"update_count":1500}
I20260812 06:19:31.557680  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=7.149875
I20260812 06:19:31.587944  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.030s	user 0.012s	sys 0.015s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":12412,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:19:31.588493  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=2.188937
I20260812 06:19:31.601173  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.012s	user 0.005s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4568,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:31.601686  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling UndoDeltaBlockGCOp(9a780e82a3a943ba83ea3a41c4030a4a): 12308958 bytes on disk
I20260812 06:19:31.602479  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: UndoDeltaBlockGCOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":88,"lbm_reads_lt_1ms":4}
I20260812 06:19:31.602991  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=1.000000
I20260812 06:19:31.723506  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.120s	user 0.098s	sys 0.015s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528891,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":527,"lbm_read_time_us":7139,"lbm_reads_lt_1ms":372,"lbm_write_time_us":20565,"lbm_writes_lt_1ms":343,"mutex_wait_us":67,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":24960,"update_count":1500}
I20260812 06:19:31.724033  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=10.126437
I20260812 06:19:31.775557  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.051s	user 0.023s	sys 0.015s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":18521,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:31.776044  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=2.188937
I20260812 06:19:31.787781  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4131,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:31.788385  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=1.000000
I20260812 06:19:31.923408  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.135s	user 0.098s	sys 0.035s 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":1261,"lbm_read_time_us":9818,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26363,"lbm_writes_lt_1ms":443,"mutex_wait_us":324,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2000}
I20260812 06:19:31.924049  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=10.126437
I20260812 06:19:31.976502  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.052s	user 0.024s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17254,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:31.977195  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=2.188937
I20260812 06:19:31.991322  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5695,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:31.992040  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=1.000000
I20260812 06:19:32.132812  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.141s	user 0.123s	sys 0.016s 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":444,"lbm_read_time_us":10924,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28636,"lbm_writes_lt_1ms":443,"mutex_wait_us":67,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":2000}
I20260812 06:19:32.133513  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=10.126437
I20260812 06:19:32.178606  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.045s	user 0.038s	sys 0.000s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17432,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:32.179082  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=2.188937
I20260812 06:19:32.191222  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4609,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:32.191826  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=1.000000
I20260812 06:19:32.324419  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.132s	user 0.100s	sys 0.032s 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":91,"lbm_read_time_us":9777,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26546,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17152,"update_count":2000}
I20260812 06:19:32.325075  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=10.126437
I20260812 06:19:32.372797  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.048s	user 0.032s	sys 0.015s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16868,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:32.373430  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=2.188937
I20260812 06:19:32.384333  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4227,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:32.384855  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=1.000000
I20260812 06:19:32.533208  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.148s	user 0.112s	sys 0.036s 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":232,"lbm_read_time_us":11855,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25076,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2000}
I20260812 06:19:32.533948  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=10.126437
I20260812 06:19:32.580422  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.046s	user 0.014s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16410,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:32.580933  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=2.188937
I20260812 06:19:32.597981  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.017s	user 0.012s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5689,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:32.598639  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=1.000000
I20260812 06:19:32.737426  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.139s	user 0.116s	sys 0.017s 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":1011,"lbm_read_time_us":10293,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24615,"lbm_writes_lt_1ms":443,"mutex_wait_us":317,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2000}
I20260812 06:19:32.738153  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=10.126437
I20260812 06:19:32.776172  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.038s	user 0.022s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16287,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:32.776809  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=2.188937
I20260812 06:19:32.791654  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5972,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:32.792158  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushMRSOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=1.000000
I20260812 06:19:32.824627  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushMRSOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.032s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1234474,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":262,"dirs.run_wall_time_us":1363,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2100,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:32.825479  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling LogGCOp(9a780e82a3a943ba83ea3a41c4030a4a): free 129320484 bytes of WAL
I20260812 06:19:32.825726  8325 log_reader.cc:385] T 9a780e82a3a943ba83ea3a41c4030a4a: removed 13 log segments from log reader
I20260812 06:19:32.825769  8325 log.cc:1079] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/9a780e82a3a943ba83ea3a41c4030a4a/wal-000000002 (ops 7-11)
I20260812 06:19:32.825799  8325 log.cc:1079] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/9a780e82a3a943ba83ea3a41c4030a4a/wal-000000003 (ops 12-16)
I20260812 06:19:32.825860  8325 log.cc:1079] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/9a780e82a3a943ba83ea3a41c4030a4a/wal-000000004 (ops 17-21)
I20260812 06:19:32.825891  8325 log.cc:1079] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/9a780e82a3a943ba83ea3a41c4030a4a/wal-000000005 (ops 22-26)
I20260812 06:19:32.825924  8325 log.cc:1079] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/9a780e82a3a943ba83ea3a41c4030a4a/wal-000000006 (ops 27-30)
I20260812 06:19:32.825960  8325 log.cc:1079] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/9a780e82a3a943ba83ea3a41c4030a4a/wal-000000007 (ops 31-35)
I20260812 06:19:32.825999  8325 log.cc:1079] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/9a780e82a3a943ba83ea3a41c4030a4a/wal-000000008 (ops 36-40)
I20260812 06:19:32.826042  8325 log.cc:1079] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/9a780e82a3a943ba83ea3a41c4030a4a/wal-000000009 (ops 41-44)
I20260812 06:19:32.826082  8325 log.cc:1079] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/9a780e82a3a943ba83ea3a41c4030a4a/wal-000000010 (ops 45-49)
I20260812 06:19:32.826121  8325 log.cc:1079] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/9a780e82a3a943ba83ea3a41c4030a4a/wal-000000011 (ops 50-54)
I20260812 06:19:32.826159  8325 log.cc:1079] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/9a780e82a3a943ba83ea3a41c4030a4a/wal-000000012 (ops 55-59)
I20260812 06:19:32.826195  8325 log.cc:1079] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/9a780e82a3a943ba83ea3a41c4030a4a/wal-000000013 (ops 60-64)
I20260812 06:19:32.826232  8325 log.cc:1079] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/9a780e82a3a943ba83ea3a41c4030a4a/wal-000000014 (ops 65-69)
I20260812 06:19:32.856509  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: LogGCOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.031s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:19:32.857024  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=3.181125
I20260812 06:19:32.871984  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":5046218,"delete_count":0,"lbm_write_time_us":5977,"lbm_writes_lt_1ms":126,"reinsert_count":0,"update_count":615}
I20260812 06:19:32.872488  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=1.196750
I20260812 06:19:32.882083  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.009s	user 0.003s	sys 0.005s Metrics: {"bytes_written":3159080,"delete_count":0,"lbm_write_time_us":3415,"lbm_writes_lt_1ms":80,"reinsert_count":0,"update_count":385}
I20260812 06:19:32.882694  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling UndoDeltaBlockGCOp(9a780e82a3a943ba83ea3a41c4030a4a): 472 bytes on disk
I20260812 06:19:32.883164  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: UndoDeltaBlockGCOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:19:32.883602  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=1.000000
I20260812 06:19:33.067448  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.184s	user 0.134s	sys 0.045s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836354,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":938,"lbm_read_time_us":13040,"lbm_reads_lt_1ms":674,"lbm_write_time_us":37297,"lbm_writes_lt_1ms":643,"mutex_wait_us":337,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7808,"thread_start_us":77,"threads_started":1,"update_count":3000}
I20260812 06:19:33.068303  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=14.095187
I20260812 06:19:33.123508  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.055s	user 0.036s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23786,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:33.123971  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=2.188937
I20260812 06:19:33.135690  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4331,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:33.136237  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=1.000000
I20260812 06:19:33.300135  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.164s	user 0.108s	sys 0.052s 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":812,"lbm_read_time_us":12430,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29398,"lbm_writes_lt_1ms":543,"mutex_wait_us":377,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":27392,"update_count":2500}
I20260812 06:19:33.300872  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=12.110812
I20260812 06:19:33.355731  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.055s	user 0.028s	sys 0.020s Metrics: {"bytes_written":13907426,"delete_count":0,"lbm_write_time_us":25156,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":341,"reinsert_count":0,"update_count":1695}
I20260812 06:19:33.356266  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=1.196750
I20260812 06:19:33.368196  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.012s	user 0.004s	sys 0.004s Metrics: {"bytes_written":2912934,"delete_count":0,"lbm_write_time_us":3442,"lbm_writes_lt_1ms":74,"reinsert_count":0,"update_count":355}
I20260812 06:19:33.368805  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=2.188937
I20260812 06:19:33.379998  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4219,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:33.380560  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=1.000000
I20260812 06:19:33.563306  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.182s	user 0.120s	sys 0.061s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1134,"lbm_read_time_us":14891,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30819,"lbm_writes_lt_1ms":543,"mutex_wait_us":74,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:19:33.563966  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=14.095187
I20260812 06:19:33.636193  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.072s	user 0.038s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21645,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:33.636814  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=2.188937
I20260812 06:19:33.653082  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.016s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6212,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:33.653716  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=1.000000
I20260812 06:19:33.865366  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.211s	user 0.143s	sys 0.068s 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":514,"lbm_read_time_us":16219,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35563,"lbm_writes_lt_1ms":543,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:19:33.866158  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=11.118625
I20260812 06:19:33.919726  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.053s	user 0.025s	sys 0.025s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17952,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:33.920346  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=2.188937
I20260812 06:19:33.930510  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3752,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:33.931010  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=1.000000
I20260812 06:19:34.083900  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.153s	user 0.104s	sys 0.048s 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":240,"lbm_read_time_us":12242,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23436,"lbm_writes_lt_1ms":443,"mutex_wait_us":60,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2000}
I20260812 06:19:34.084671  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=6.157687
I20260812 06:19:34.112006  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.027s	user 0.012s	sys 0.008s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9666,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:19:34.112555  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=1.000000
I20260812 06:19:34.196904  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.084s	user 0.071s	sys 0.013s Metrics: {"cfile_cache_miss":231,"cfile_cache_miss_bytes":12426369,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1076,"lbm_read_time_us":5026,"lbm_reads_lt_1ms":263,"lbm_write_time_us":15445,"lbm_writes_lt_1ms":243,"mutex_wait_us":353,"peak_mem_usage":25836184,"reinsert_count":0,"update_count":1000}
I20260812 06:19:34.197633  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=7.149875
I20260812 06:19:34.234617  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.037s	user 0.020s	sys 0.015s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":11013,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:19:34.235239  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=2.188937
I20260812 06:19:34.252144  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.017s	user 0.007s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6244,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:34.252864  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=1.000000
I20260812 06:19:34.376075  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.123s	user 0.072s	sys 0.050s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528891,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":749,"lbm_read_time_us":10469,"lbm_reads_lt_1ms":372,"lbm_write_time_us":19464,"lbm_writes_lt_1ms":343,"mutex_wait_us":31,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":1500}
I20260812 06:19:34.376929  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=7.149875
I20260812 06:19:34.402458  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.025s	user 0.015s	sys 0.009s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":10517,"lbm_writes_lt_1ms":213,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":1050}
I20260812 06:19:34.403023  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=2.188937
I20260812 06:19:34.419301  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6090,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:34.419839  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushMRSOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=1.000000
I20260812 06:19:34.447487  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushMRSOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.027s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":87,"dirs.run_cpu_time_us":203,"dirs.run_wall_time_us":1897,"drs_written":1,"lbm_read_time_us":88,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1599,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:34.448374  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling LogGCOp(9a780e82a3a943ba83ea3a41c4030a4a): free 112239331 bytes of WAL
I20260812 06:19:34.448642  8325 log_reader.cc:385] T 9a780e82a3a943ba83ea3a41c4030a4a: removed 11 log segments from log reader
I20260812 06:19:34.448740  8325 log.cc:1079] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/9a780e82a3a943ba83ea3a41c4030a4a/wal-000000015 (ops 70-74)
I20260812 06:19:34.448828  8325 log.cc:1079] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/9a780e82a3a943ba83ea3a41c4030a4a/wal-000000016 (ops 75-79)
I20260812 06:19:34.448869  8325 log.cc:1079] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/9a780e82a3a943ba83ea3a41c4030a4a/wal-000000017 (ops 80-84)
I20260812 06:19:34.448912  8325 log.cc:1079] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/9a780e82a3a943ba83ea3a41c4030a4a/wal-000000018 (ops 85-89)
I20260812 06:19:34.448951  8325 log.cc:1079] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/9a780e82a3a943ba83ea3a41c4030a4a/wal-000000019 (ops 90-94)
I20260812 06:19:34.448988  8325 log.cc:1079] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/9a780e82a3a943ba83ea3a41c4030a4a/wal-000000020 (ops 95-99)
I20260812 06:19:34.449025  8325 log.cc:1079] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/9a780e82a3a943ba83ea3a41c4030a4a/wal-000000021 (ops 100-104)
I20260812 06:19:34.449062  8325 log.cc:1079] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/9a780e82a3a943ba83ea3a41c4030a4a/wal-000000022 (ops 105-108)
I20260812 06:19:34.449100  8325 log.cc:1079] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/9a780e82a3a943ba83ea3a41c4030a4a/wal-000000023 (ops 109-113)
I20260812 06:19:34.449138  8325 log.cc:1079] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/9a780e82a3a943ba83ea3a41c4030a4a/wal-000000024 (ops 114-118)
I20260812 06:19:34.449177  8325 log.cc:1079] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/9a780e82a3a943ba83ea3a41c4030a4a/wal-000000025 (ops 119-123)
I20260812 06:19:34.475764  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: LogGCOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.027s	user 0.002s	sys 0.023s Metrics: {}
I20260812 06:19:34.476327  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling UndoDeltaBlockGCOp(9a780e82a3a943ba83ea3a41c4030a4a): 463 bytes on disk
I20260812 06:19:34.476900  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: UndoDeltaBlockGCOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:19:34.477558  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=3.181125
I20260812 06:19:34.491048  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.013s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4811,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:34.491756  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling LogGCOp(9a780e82a3a943ba83ea3a41c4030a4a): free 12017932 bytes of WAL
I20260812 06:19:34.492028  8325 log_reader.cc:385] T 9a780e82a3a943ba83ea3a41c4030a4a: removed 1 log segments from log reader
I20260812 06:19:34.492097  8325 log.cc:1079] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/9a780e82a3a943ba83ea3a41c4030a4a/wal-000000026 (ops 124-128)
I20260812 06:19:34.494659  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: LogGCOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:34.494972  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=2.188937
I20260812 06:19:34.506305  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3889,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:34.506774  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=1.000000
I20260812 06:19:34.659972  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.153s	user 0.108s	sys 0.040s Metrics: {"cfile_cache_miss":534,"cfile_cache_miss_bytes":24733940,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":513,"lbm_read_time_us":10746,"lbm_reads_lt_1ms":574,"lbm_write_time_us":30134,"lbm_writes_lt_1ms":543,"mutex_wait_us":60,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12416,"thread_start_us":86,"threads_started":1,"update_count":2500}
I20260812 06:19:34.660763  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=11.118625
I20260812 06:19:34.701373  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.040s	user 0.036s	sys 0.004s Metrics: {"bytes_written":12840814,"delete_count":0,"lbm_write_time_us":17199,"lbm_writes_lt_1ms":316,"reinsert_count":0,"update_count":1565}
I20260812 06:19:34.701880  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=2.188937
I20260812 06:19:34.724246  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.022s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3569330,"delete_count":0,"lbm_write_time_us":5739,"lbm_writes_lt_1ms":90,"reinsert_count":0,"update_count":435}
I20260812 06:19:34.724797  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=2.188937
I20260812 06:19:34.736323  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4393,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:34.737082  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=1.000000
I20260812 06:19:34.896442  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.159s	user 0.129s	sys 0.029s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733838,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":842,"lbm_read_time_us":12961,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31557,"lbm_writes_lt_1ms":543,"mutex_wait_us":399,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:19:34.898325  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=10.126437
I20260812 06:19:34.930837  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.032s	user 0.018s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14136,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":1500}
I20260812 06:19:34.931419  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=2.188937
I20260812 06:19:34.946520  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.015s	user 0.004s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5181,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:34.947070  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=1.000000
I20260812 06:19:35.074343  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.127s	user 0.093s	sys 0.033s 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":285,"lbm_read_time_us":7627,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26851,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2000}
I20260812 06:19:35.075310  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=10.126437
I20260812 06:19:35.123533  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.048s	user 0.023s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":24040,"lbm_writes_1-10_ms":4,"lbm_writes_lt_1ms":299,"reinsert_count":0,"update_count":1500}
I20260812 06:19:35.124034  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=2.188937
I20260812 06:19:35.137504  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.013s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4918,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:35.138065  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=1.000000
I20260812 06:19:35.264674  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.126s	user 0.105s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":277,"lbm_read_time_us":10145,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25838,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13952,"update_count":2000}
I20260812 06:19:35.265369  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=10.126437
I20260812 06:19:35.322592  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.057s	user 0.026s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17641,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:35.323225  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=2.188937
I20260812 06:19:35.334745  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4281,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:35.335232  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=1.000000
I20260812 06:19:35.482214  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.147s	user 0.104s	sys 0.042s 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":459,"lbm_read_time_us":10310,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24037,"lbm_writes_lt_1ms":443,"mutex_wait_us":68,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":20096,"update_count":2000}
I20260812 06:19:35.485484  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=10.126437
I20260812 06:19:35.525758  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.040s	user 0.022s	sys 0.017s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16139,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:35.526324  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=2.188937
I20260812 06:19:35.539702  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.013s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5103,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:35.540266  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=1.000000
I20260812 06:19:35.668001  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.127s	user 0.094s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":977,"lbm_read_time_us":7885,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25003,"lbm_writes_lt_1ms":443,"mutex_wait_us":328,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":20096,"update_count":2000}
I20260812 06:19:35.668960  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=10.126437
I20260812 06:19:35.711733  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.043s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15565,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:35.712318  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=2.188937
I20260812 06:19:35.724637  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4447,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:35.725325  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=1.000000
I20260812 06:19:35.858963  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.133s	user 0.114s	sys 0.019s 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":1003,"lbm_read_time_us":9155,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26883,"lbm_writes_lt_1ms":443,"mutex_wait_us":307,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2000}
I20260812 06:19:35.859759  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=10.126437
I20260812 06:19:35.900754  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.041s	user 0.021s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15232,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:35.901412  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=2.188937
I20260812 06:19:35.913311  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.012s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4328,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:35.913844  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushMRSOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=1.000000
I20260812 06:19:35.946055  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushMRSOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.032s	user 0.026s	sys 0.004s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":251,"dirs.run_wall_time_us":1474,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1661,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:35.946843  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling LogGCOp(9a780e82a3a943ba83ea3a41c4030a4a): free 121459759 bytes of WAL
I20260812 06:19:35.947080  8325 log_reader.cc:385] T 9a780e82a3a943ba83ea3a41c4030a4a: removed 12 log segments from log reader
I20260812 06:19:35.947124  8325 log.cc:1079] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/9a780e82a3a943ba83ea3a41c4030a4a/wal-000000027 (ops 129-133)
I20260812 06:19:35.947152  8325 log.cc:1079] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/9a780e82a3a943ba83ea3a41c4030a4a/wal-000000028 (ops 134-138)
I20260812 06:19:35.947216  8325 log.cc:1079] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/9a780e82a3a943ba83ea3a41c4030a4a/wal-000000029 (ops 139-143)
I20260812 06:19:35.947244  8325 log.cc:1079] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/9a780e82a3a943ba83ea3a41c4030a4a/wal-000000030 (ops 144-148)
I20260812 06:19:35.947288  8325 log.cc:1079] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/9a780e82a3a943ba83ea3a41c4030a4a/wal-000000031 (ops 149-153)
I20260812 06:19:35.947328  8325 log.cc:1079] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/9a780e82a3a943ba83ea3a41c4030a4a/wal-000000032 (ops 154-158)
I20260812 06:19:35.947367  8325 log.cc:1079] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/9a780e82a3a943ba83ea3a41c4030a4a/wal-000000033 (ops 159-163)
I20260812 06:19:35.947404  8325 log.cc:1079] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/9a780e82a3a943ba83ea3a41c4030a4a/wal-000000034 (ops 164-168)
I20260812 06:19:35.947441  8325 log.cc:1079] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/9a780e82a3a943ba83ea3a41c4030a4a/wal-000000035 (ops 169-173)
I20260812 06:19:35.947479  8325 log.cc:1079] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/9a780e82a3a943ba83ea3a41c4030a4a/wal-000000036 (ops 174-178)
I20260812 06:19:35.947515  8325 log.cc:1079] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/9a780e82a3a943ba83ea3a41c4030a4a/wal-000000037 (ops 179-183)
I20260812 06:19:35.947551  8325 log.cc:1079] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/9a780e82a3a943ba83ea3a41c4030a4a/wal-000000038 (ops 184-188)
I20260812 06:19:35.975312  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: LogGCOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:35.975811  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=6.157687
I20260812 06:19:35.997536  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.022s	user 0.017s	sys 0.003s Metrics: {"bytes_written":7589714,"delete_count":0,"lbm_write_time_us":8887,"lbm_writes_lt_1ms":188,"reinsert_count":0,"update_count":925}
I20260812 06:19:35.998224  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling UndoDeltaBlockGCOp(9a780e82a3a943ba83ea3a41c4030a4a): 482 bytes on disk
I20260812 06:19:35.999011  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: UndoDeltaBlockGCOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:19:35.999639  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=1.000000
I20260812 06:19:36.182088  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.182s	user 0.135s	sys 0.040s Metrics: {"cfile_cache_miss":618,"cfile_cache_miss_bytes":28220891,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":178,"lbm_read_time_us":11280,"lbm_reads_lt_1ms":650,"lbm_write_time_us":38054,"lbm_writes_lt_1ms":628,"mutex_wait_us":28,"peak_mem_usage":72846179,"reinsert_count":0,"spinlock_wait_cycles":70784,"thread_start_us":79,"threads_started":1,"update_count":2925}
I20260812 06:19:36.182861  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=15.087375
I20260812 06:19:36.241194  8204 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.093s	user 1.896s	sys 0.137s
I20260812 06:19:36.245437  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.062s	user 0.029s	sys 0.016s Metrics: {"bytes_written":17025269,"delete_count":0,"lbm_write_time_us":20444,"lbm_writes_lt_1ms":418,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2075}
I20260812 06:19:36.245975  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=2.188937
I20260812 06:19:36.264050  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: FlushDeltaMemStoresOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.018s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7317,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":500}
I20260812 06:19:36.264788  8398 maintenance_manager.cc:419] P 9ae4771bd9214aa7a946edca370859de: Scheduling MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a): perf score=1.000000
I20260812 06:19:36.298038  8204 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.056s	user 0.003s	sys 0.000s
I20260812 06:19:36.298733  8204 tablet_server.cc:179] TabletServer@127.8.3.1:0 shutting down...
I20260812 06:19:36.382627  8325 maintenance_manager.cc:643] P 9ae4771bd9214aa7a946edca370859de: MajorDeltaCompactionOp(9a780e82a3a943ba83ea3a41c4030a4a) complete. Timing: real 0.118s	user 0.088s	sys 0.029s Metrics: {"cfile_cache_hit":379,"cfile_cache_hit_bytes":15507728,"cfile_cache_miss":168,"cfile_cache_miss_bytes":9841363,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":576,"lbm_read_time_us":4250,"lbm_reads_lt_1ms":200,"lbm_write_time_us":27041,"lbm_writes_lt_1ms":558,"peak_mem_usage":64771809,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2575}
I20260812 06:19:36.383716  8204 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:36.384246  8204 tablet_replica.cc:333] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de: stopping tablet replica
I20260812 06:19:36.384517  8204 raft_consensus.cc:2243] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:36.384835  8204 raft_consensus.cc:2272] T 9a780e82a3a943ba83ea3a41c4030a4a P 9ae4771bd9214aa7a946edca370859de [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:36.401357  8204 tablet_server.cc:196] TabletServer@127.8.3.1:0 shutdown complete.
I20260812 06:19:36.432313  8204 master.cc:562] Master@127.8.3.62:34893 shutting down...
I20260812 06:19:36.437132  8204 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 571edc7984e44d5e9cac71b24a8a305e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:36.437358  8204 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 571edc7984e44d5e9cac71b24a8a305e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:36.437466  8204 tablet_replica.cc:333] T 00000000000000000000000000000000 P 571edc7984e44d5e9cac71b24a8a305e: stopping tablet replica
I20260812 06:19:36.451148  8204 master.cc:584] Master@127.8.3.62:34893 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5717 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:36.560010  8204 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.8.3.62:38797
I20260812 06:19:36.560472  8204 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:36.562776  8438 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:36.562821  8436 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:36.562898  8204 server_base.cc:1061] running on GCE node
W20260812 06:19:36.562832  8435 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:36.563212  8204 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:36.563261  8204 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:36.563277  8204 hybrid_clock.cc:648] HybridClock initialized: now 1786515576563277 us; error 0 us; skew 500 ppm
I20260812 06:19:36.564217  8204 webserver.cc:533] Webserver started at http://127.8.3.62:45049/ using document root <none> and password file <none>
I20260812 06:19:36.564414  8204 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:36.564469  8204 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:36.564587  8204 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:36.565726  8204 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/master-0-root/instance:
uuid: "44dce69474b34a1486232dbf9f56b5f8"
format_stamp: "Formatted at 2026-08-12 06:19:36 on dist-test-slave-cbsf"
I20260812 06:19:36.567288  8204 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:36.568216  8444 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:36.568485  8204 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:36.568552  8204 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/master-0-root
uuid: "44dce69474b34a1486232dbf9f56b5f8"
format_stamp: "Formatted at 2026-08-12 06:19:36 on dist-test-slave-cbsf"
I20260812 06:19:36.568662  8204 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-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:36.579968  8204 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:36.580430  8204 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:36.584903  8204 rpc_server.cc:307] RPC server started. Bound to: 127.8.3.62:38797
I20260812 06:19:36.589917  8509 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.3.62:38797 every 8 connection(s)
I20260812 06:19:36.590415  8510 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:36.592309  8510 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 44dce69474b34a1486232dbf9f56b5f8: Bootstrap starting.
I20260812 06:19:36.593181  8510 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 44dce69474b34a1486232dbf9f56b5f8: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:36.594306  8510 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 44dce69474b34a1486232dbf9f56b5f8: No bootstrap required, opened a new log
I20260812 06:19:36.594792  8510 raft_consensus.cc:359] T 00000000000000000000000000000000 P 44dce69474b34a1486232dbf9f56b5f8 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "44dce69474b34a1486232dbf9f56b5f8" member_type: VOTER }
I20260812 06:19:36.594887  8510 raft_consensus.cc:385] T 00000000000000000000000000000000 P 44dce69474b34a1486232dbf9f56b5f8 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:36.594946  8510 raft_consensus.cc:740] T 00000000000000000000000000000000 P 44dce69474b34a1486232dbf9f56b5f8 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 44dce69474b34a1486232dbf9f56b5f8, State: Initialized, Role: FOLLOWER
I20260812 06:19:36.595139  8510 consensus_queue.cc:260] T 00000000000000000000000000000000 P 44dce69474b34a1486232dbf9f56b5f8 [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: "44dce69474b34a1486232dbf9f56b5f8" member_type: VOTER }
I20260812 06:19:36.595217  8510 raft_consensus.cc:399] T 00000000000000000000000000000000 P 44dce69474b34a1486232dbf9f56b5f8 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:36.595284  8510 raft_consensus.cc:493] T 00000000000000000000000000000000 P 44dce69474b34a1486232dbf9f56b5f8 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:36.595343  8510 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 44dce69474b34a1486232dbf9f56b5f8 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:36.596079  8510 raft_consensus.cc:515] T 00000000000000000000000000000000 P 44dce69474b34a1486232dbf9f56b5f8 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "44dce69474b34a1486232dbf9f56b5f8" member_type: VOTER }
I20260812 06:19:36.596236  8510 leader_election.cc:304] T 00000000000000000000000000000000 P 44dce69474b34a1486232dbf9f56b5f8 [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: 44dce69474b34a1486232dbf9f56b5f8; no voters: 
I20260812 06:19:36.596465  8510 leader_election.cc:290] T 00000000000000000000000000000000 P 44dce69474b34a1486232dbf9f56b5f8 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:36.596634  8514 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 44dce69474b34a1486232dbf9f56b5f8 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:36.596877  8514 raft_consensus.cc:697] T 00000000000000000000000000000000 P 44dce69474b34a1486232dbf9f56b5f8 [term 1 LEADER]: Becoming Leader. State: Replica: 44dce69474b34a1486232dbf9f56b5f8, State: Running, Role: LEADER
I20260812 06:19:36.596964  8510 sys_catalog.cc:565] T 00000000000000000000000000000000 P 44dce69474b34a1486232dbf9f56b5f8 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:36.597041  8514 consensus_queue.cc:237] T 00000000000000000000000000000000 P 44dce69474b34a1486232dbf9f56b5f8 [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: "44dce69474b34a1486232dbf9f56b5f8" member_type: VOTER }
I20260812 06:19:36.597558  8515 sys_catalog.cc:455] T 00000000000000000000000000000000 P 44dce69474b34a1486232dbf9f56b5f8 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "44dce69474b34a1486232dbf9f56b5f8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "44dce69474b34a1486232dbf9f56b5f8" member_type: VOTER } }
I20260812 06:19:36.597623  8516 sys_catalog.cc:455] T 00000000000000000000000000000000 P 44dce69474b34a1486232dbf9f56b5f8 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 44dce69474b34a1486232dbf9f56b5f8. Latest consensus state: current_term: 1 leader_uuid: "44dce69474b34a1486232dbf9f56b5f8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "44dce69474b34a1486232dbf9f56b5f8" member_type: VOTER } }
I20260812 06:19:36.597677  8515 sys_catalog.cc:458] T 00000000000000000000000000000000 P 44dce69474b34a1486232dbf9f56b5f8 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:36.597709  8516 sys_catalog.cc:458] T 00000000000000000000000000000000 P 44dce69474b34a1486232dbf9f56b5f8 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:36.597922  8523 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:36.598822  8523 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:36.598999  8204 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:36.600636  8523 catalog_manager.cc:1383] Generated new cluster ID: 3d77ce57fedc416594a9be55843abe6d
I20260812 06:19:36.600718  8523 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:36.625240  8523 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:36.625876  8523 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:36.635398  8523 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 44dce69474b34a1486232dbf9f56b5f8: Generated new TSK 0
I20260812 06:19:36.635637  8523 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:36.663751  8204 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:36.666095  8537 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:36.666188  8204 server_base.cc:1061] running on GCE node
W20260812 06:19:36.666131  8540 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:36.666219  8538 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:36.666520  8204 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:36.666594  8204 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:36.666620  8204 hybrid_clock.cc:648] HybridClock initialized: now 1786515576666620 us; error 0 us; skew 500 ppm
I20260812 06:19:36.667539  8204 webserver.cc:533] Webserver started at http://127.8.3.1:41783/ using document root <none> and password file <none>
I20260812 06:19:36.667730  8204 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:36.667806  8204 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:36.667891  8204 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:36.668334  8204 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root/instance:
uuid: "fce499c9f9934385a42513767641973a"
format_stamp: "Formatted at 2026-08-12 06:19:36 on dist-test-slave-cbsf"
I20260812 06:19:36.670112  8204 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:19:36.671166  8545 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:36.671433  8204 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:36.671500  8204 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root
uuid: "fce499c9f9934385a42513767641973a"
format_stamp: "Formatted at 2026-08-12 06:19:36 on dist-test-slave-cbsf"
I20260812 06:19:36.671607  8204 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-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:36.694124  8204 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:36.694622  8204 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:36.695010  8204 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:36.695531  8204 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:36.695571  8204 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:36.695634  8204 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:36.695679  8204 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:36.700495  8204 rpc_server.cc:307] RPC server started. Bound to: 127.8.3.1:42311
I20260812 06:19:36.703612  8617 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.3.1:42311 every 8 connection(s)
I20260812 06:19:36.713308  8619 heartbeater.cc:344] Connected to a master server at 127.8.3.62:38797
I20260812 06:19:36.713588  8619 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:36.713892  8619 heartbeater.cc:507] Master 127.8.3.62:38797 requested a full tablet report, sending...
I20260812 06:19:36.714742  8466 ts_manager.cc:194] Registered new tserver with Master: fce499c9f9934385a42513767641973a (127.8.3.1:42311)
I20260812 06:19:36.715517  8466 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:52384
I20260812 06:19:36.715752  8204 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.014510604s
I20260812 06:19:36.722892  8466 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:52394:
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:36.732216  8577 tablet_service.cc:1511] Processing CreateTablet for tablet a41177872875457dbe2c775fdba931a1 (DEFAULT_TABLE table=heavy-update-compaction-test [id=00fcc61f8be14cb4bb7f48582aeef55c]), partition=
I20260812 06:19:36.732482  8577 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet a41177872875457dbe2c775fdba931a1. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:36.734766  8632 tablet_bootstrap.cc:492] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Bootstrap starting.
I20260812 06:19:36.735632  8632 tablet_bootstrap.cc:654] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:36.737027  8632 tablet_bootstrap.cc:492] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: No bootstrap required, opened a new log
I20260812 06:19:36.737146  8632 ts_tablet_manager.cc:1403] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:36.737663  8632 raft_consensus.cc:359] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fce499c9f9934385a42513767641973a" member_type: VOTER last_known_addr { host: "127.8.3.1" port: 42311 } }
I20260812 06:19:36.737789  8632 raft_consensus.cc:385] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:36.737834  8632 raft_consensus.cc:740] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: fce499c9f9934385a42513767641973a, State: Initialized, Role: FOLLOWER
I20260812 06:19:36.737975  8632 consensus_queue.cc:260] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a [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: "fce499c9f9934385a42513767641973a" member_type: VOTER last_known_addr { host: "127.8.3.1" port: 42311 } }
I20260812 06:19:36.738070  8632 raft_consensus.cc:399] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:36.738116  8632 raft_consensus.cc:493] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:36.738170  8632 raft_consensus.cc:3060] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:36.738921  8632 raft_consensus.cc:515] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fce499c9f9934385a42513767641973a" member_type: VOTER last_known_addr { host: "127.8.3.1" port: 42311 } }
I20260812 06:19:36.739091  8632 leader_election.cc:304] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a [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: fce499c9f9934385a42513767641973a; no voters: 
I20260812 06:19:36.739317  8632 leader_election.cc:290] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:36.739452  8634 raft_consensus.cc:2804] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:36.739705  8634 raft_consensus.cc:697] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a [term 1 LEADER]: Becoming Leader. State: Replica: fce499c9f9934385a42513767641973a, State: Running, Role: LEADER
I20260812 06:19:36.739717  8632 ts_tablet_manager.cc:1434] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:19:36.739702  8619 heartbeater.cc:499] Master 127.8.3.62:38797 was elected leader, sending a full tablet report...
I20260812 06:19:36.739919  8634 consensus_queue.cc:237] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a [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: "fce499c9f9934385a42513767641973a" member_type: VOTER last_known_addr { host: "127.8.3.1" port: 42311 } }
I20260812 06:19:36.741343  8466 catalog_manager.cc:5719] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a reported cstate change: term changed from 0 to 1, leader changed from <none> to fce499c9f9934385a42513767641973a (127.8.3.1). New cstate: current_term: 1 leader_uuid: "fce499c9f9934385a42513767641973a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fce499c9f9934385a42513767641973a" member_type: VOTER last_known_addr { host: "127.8.3.1" port: 42311 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:36.806578  8204 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.059s	user 0.021s	sys 0.004s
I20260812 06:19:36.954252  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushMRSOp(a41177872875457dbe2c775fdba931a1): perf score=19.054940
I20260812 06:19:37.122007  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushMRSOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.167s	user 0.115s	sys 0.051s Metrics: {"bytes_written":9025564,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":111,"dirs.run_cpu_time_us":227,"dirs.run_wall_time_us":1039,"drs_written":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39461,"lbm_writes_lt_1ms":677,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":12800,"update_count":1100}
I20260812 06:19:37.122750  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling LogGCOp(a41177872875457dbe2c775fdba931a1): free 20290830 bytes of WAL
I20260812 06:19:37.123037  8551 log_reader.cc:385] T a41177872875457dbe2c775fdba931a1: removed 2 log segments from log reader
I20260812 06:19:37.123087  8551 log.cc:1079] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/a41177872875457dbe2c775fdba931a1/wal-000000001 (ops 1-6)
I20260812 06:19:37.123121  8551 log.cc:1079] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/a41177872875457dbe2c775fdba931a1/wal-000000002 (ops 7-10)
I20260812 06:19:37.127753  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: LogGCOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.005s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:37.128177  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling UndoDeltaBlockGCOp(a41177872875457dbe2c775fdba931a1): 16411392 bytes on disk
I20260812 06:19:37.128661  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: UndoDeltaBlockGCOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:19:37.129148  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1): perf score=2.188937
I20260812 06:19:37.143771  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3282155,"delete_count":0,"lbm_write_time_us":4824,"lbm_writes_lt_1ms":83,"reinsert_count":0,"update_count":400}
I20260812 06:19:37.144394  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling MajorDeltaCompactionOp(a41177872875457dbe2c775fdba931a1): perf score=1.000000
I20260812 06:19:37.278931  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: MajorDeltaCompactionOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.134s	user 0.086s	sys 0.048s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16569847,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":571,"lbm_read_time_us":9948,"lbm_reads_lt_1ms":360,"lbm_write_time_us":21593,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":2560,"thread_start_us":312,"threads_started":5,"update_count":1500}
I20260812 06:19:37.279520  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1): perf score=10.126437
I20260812 06:19:37.321594  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.042s	user 0.033s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18356,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:37.322152  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling MajorDeltaCompactionOp(a41177872875457dbe2c775fdba931a1): perf score=1.000000
I20260812 06:19:37.433540  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: MajorDeltaCompactionOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.111s	user 0.087s	sys 0.024s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1033,"lbm_read_time_us":7569,"lbm_reads_lt_1ms":363,"lbm_write_time_us":20151,"lbm_writes_lt_1ms":343,"mutex_wait_us":366,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":50048,"update_count":1500}
I20260812 06:19:37.434080  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1): perf score=10.126437
I20260812 06:19:37.480404  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.046s	user 0.030s	sys 0.008s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":18717,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:37.481034  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling MajorDeltaCompactionOp(a41177872875457dbe2c775fdba931a1): perf score=1.000000
I20260812 06:19:37.597810  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: MajorDeltaCompactionOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.117s	user 0.088s	sys 0.028s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569748,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":428,"lbm_read_time_us":9094,"lbm_reads_lt_1ms":363,"lbm_write_time_us":22248,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":1500}
I20260812 06:19:37.598452  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1): perf score=10.126437
I20260812 06:19:37.649236  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.051s	user 0.023s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19463,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:37.649731  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1): perf score=2.188937
I20260812 06:19:37.662508  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4467,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:37.663188  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling MajorDeltaCompactionOp(a41177872875457dbe2c775fdba931a1): perf score=1.000000
I20260812 06:19:37.820480  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: MajorDeltaCompactionOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.156s	user 0.132s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":190,"lbm_read_time_us":11427,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29376,"lbm_writes_lt_1ms":443,"mutex_wait_us":1,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":2000}
I20260812 06:19:37.821167  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1): perf score=10.126437
I20260812 06:19:37.869720  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.048s	user 0.025s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18477,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:37.870297  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1): perf score=2.188937
I20260812 06:19:37.886533  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6125,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:37.887156  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling MajorDeltaCompactionOp(a41177872875457dbe2c775fdba931a1): perf score=1.000000
I20260812 06:19:38.025846  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: MajorDeltaCompactionOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.138s	user 0.106s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":564,"lbm_read_time_us":10427,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26694,"lbm_writes_lt_1ms":443,"mutex_wait_us":355,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":24448,"update_count":2000}
I20260812 06:19:38.026583  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1): perf score=10.126437
I20260812 06:19:38.061703  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.035s	user 0.028s	sys 0.004s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14487,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:38.062330  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1): perf score=2.188937
I20260812 06:19:38.076797  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.014s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4968,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.077332  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling MajorDeltaCompactionOp(a41177872875457dbe2c775fdba931a1): perf score=1.000000
I20260812 06:19:38.239053  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: MajorDeltaCompactionOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.162s	user 0.136s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":823,"lbm_read_time_us":10258,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28234,"lbm_writes_lt_1ms":443,"mutex_wait_us":305,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9728,"update_count":2000}
I20260812 06:19:38.239789  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1): perf score=11.118625
I20260812 06:19:38.283991  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.044s	user 0.026s	sys 0.015s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":13473,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:38.284854  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1): perf score=2.188937
I20260812 06:19:38.298422  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.013s	user 0.003s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5281,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:38.298880  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling MajorDeltaCompactionOp(a41177872875457dbe2c775fdba931a1): perf score=1.000000
I20260812 06:19:38.462431  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: MajorDeltaCompactionOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.163s	user 0.082s	sys 0.076s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":253,"lbm_read_time_us":11134,"lbm_reads_lt_1ms":468,"lbm_write_time_us":25613,"lbm_writes_lt_1ms":443,"mutex_wait_us":67,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:38.463129  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1): perf score=14.095187
I20260812 06:19:38.517342  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.054s	user 0.035s	sys 0.011s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20615,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:38.517935  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1): perf score=2.188937
I20260812 06:19:38.530313  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4408,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.530817  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushMRSOp(a41177872875457dbe2c775fdba931a1): perf score=1.000000
I20260812 06:19:38.559958  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushMRSOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.029s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":207,"dirs.run_wall_time_us":1301,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1754,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:38.560667  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling LogGCOp(a41177872875457dbe2c775fdba931a1): free 121006386 bytes of WAL
I20260812 06:19:38.560978  8551 log_reader.cc:385] T a41177872875457dbe2c775fdba931a1: removed 12 log segments from log reader
I20260812 06:19:38.561058  8551 log.cc:1079] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/a41177872875457dbe2c775fdba931a1/wal-000000003 (ops 11-15)
I20260812 06:19:38.561117  8551 log.cc:1079] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/a41177872875457dbe2c775fdba931a1/wal-000000004 (ops 16-20)
I20260812 06:19:38.561157  8551 log.cc:1079] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/a41177872875457dbe2c775fdba931a1/wal-000000005 (ops 21-25)
I20260812 06:19:38.561195  8551 log.cc:1079] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/a41177872875457dbe2c775fdba931a1/wal-000000006 (ops 26-30)
I20260812 06:19:38.561233  8551 log.cc:1079] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/a41177872875457dbe2c775fdba931a1/wal-000000007 (ops 31-35)
I20260812 06:19:38.561269  8551 log.cc:1079] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/a41177872875457dbe2c775fdba931a1/wal-000000008 (ops 36-40)
I20260812 06:19:38.561307  8551 log.cc:1079] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/a41177872875457dbe2c775fdba931a1/wal-000000009 (ops 41-45)
I20260812 06:19:38.561343  8551 log.cc:1079] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/a41177872875457dbe2c775fdba931a1/wal-000000010 (ops 46-50)
I20260812 06:19:38.561381  8551 log.cc:1079] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/a41177872875457dbe2c775fdba931a1/wal-000000011 (ops 51-55)
I20260812 06:19:38.561419  8551 log.cc:1079] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/a41177872875457dbe2c775fdba931a1/wal-000000012 (ops 56-60)
I20260812 06:19:38.561455  8551 log.cc:1079] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/a41177872875457dbe2c775fdba931a1/wal-000000013 (ops 61-64)
I20260812 06:19:38.561491  8551 log.cc:1079] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/a41177872875457dbe2c775fdba931a1/wal-000000014 (ops 65-69)
I20260812 06:19:38.592532  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: LogGCOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.032s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:19:38.596131  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1): perf score=2.188937
I20260812 06:19:38.615398  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.019s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4702,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.615839  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1): perf score=2.188937
I20260812 06:19:38.627022  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4452,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.627565  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling UndoDeltaBlockGCOp(a41177872875457dbe2c775fdba931a1): 473 bytes on disk
I20260812 06:19:38.628016  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: UndoDeltaBlockGCOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:19:38.628480  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling MajorDeltaCompactionOp(a41177872875457dbe2c775fdba931a1): perf score=1.000000
I20260812 06:19:38.884995  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: MajorDeltaCompactionOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.256s	user 0.156s	sys 0.088s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979752,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":982,"lbm_read_time_us":17268,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39128,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":17152,"thread_start_us":87,"threads_started":1,"update_count":3500}
I20260812 06:19:38.885844  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1): perf score=18.063937
I20260812 06:19:38.947922  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.062s	user 0.045s	sys 0.012s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":28083,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:38.948391  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling MajorDeltaCompactionOp(a41177872875457dbe2c775fdba931a1): perf score=1.000000
I20260812 06:19:39.138092  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: MajorDeltaCompactionOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.190s	user 0.137s	sys 0.048s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24774572,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":583,"lbm_read_time_us":14160,"lbm_reads_lt_1ms":563,"lbm_write_time_us":32386,"lbm_writes_lt_1ms":543,"mutex_wait_us":284,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:19:39.138720  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1): perf score=15.087375
I20260812 06:19:39.211185  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.072s	user 0.033s	sys 0.026s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":23432,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:39.211853  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1): perf score=6.157687
I20260812 06:19:39.232661  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.021s	user 0.007s	sys 0.011s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":8742,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:19:39.233296  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling MajorDeltaCompactionOp(a41177872875457dbe2c775fdba931a1): perf score=1.000000
I20260812 06:19:39.458050  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: MajorDeltaCompactionOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.225s	user 0.155s	sys 0.069s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877101,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1435,"lbm_read_time_us":15851,"lbm_reads_lt_1ms":672,"lbm_write_time_us":37708,"lbm_writes_lt_1ms":643,"mutex_wait_us":368,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14208,"update_count":3000}
I20260812 06:19:39.458608  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1): perf score=14.095187
I20260812 06:19:39.520623  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.062s	user 0.024s	sys 0.020s Metrics: {"bytes_written":16409940,"delete_count":0,"lbm_write_time_us":22381,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:39.521287  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1): perf score=2.188937
I20260812 06:19:39.533562  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.012s	user 0.008s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4404,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:39.534049  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling MajorDeltaCompactionOp(a41177872875457dbe2c775fdba931a1): perf score=1.000000
I20260812 06:19:39.711153  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: MajorDeltaCompactionOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.177s	user 0.119s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774727,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1034,"lbm_read_time_us":13232,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30364,"lbm_writes_lt_1ms":543,"mutex_wait_us":292,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":39552,"update_count":2500}
I20260812 06:19:39.711706  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1): perf score=14.095187
I20260812 06:19:39.773871  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.062s	user 0.040s	sys 0.008s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20938,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:39.774405  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1): perf score=2.188937
I20260812 06:19:39.786384  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4419,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:39.787015  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling MajorDeltaCompactionOp(a41177872875457dbe2c775fdba931a1): perf score=1.000000
I20260812 06:19:39.983814  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: MajorDeltaCompactionOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.197s	user 0.122s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":182,"lbm_read_time_us":14411,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32527,"lbm_writes_lt_1ms":543,"mutex_wait_us":72,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2500}
I20260812 06:19:39.984633  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1): perf score=14.095187
I20260812 06:19:40.046588  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.062s	user 0.035s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19100,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:40.047220  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1): perf score=2.188937
I20260812 06:19:40.065007  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.018s	user 0.010s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6769,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.065765  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushMRSOp(a41177872875457dbe2c775fdba931a1): perf score=1.000000
I20260812 06:19:40.111915  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushMRSOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.046s	user 0.030s	sys 0.004s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":230,"dirs.run_wall_time_us":1414,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1739,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:40.112759  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling LogGCOp(a41177872875457dbe2c775fdba931a1): free 112692422 bytes of WAL
I20260812 06:19:40.113010  8551 log_reader.cc:385] T a41177872875457dbe2c775fdba931a1: removed 11 log segments from log reader
I20260812 06:19:40.113085  8551 log.cc:1079] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/a41177872875457dbe2c775fdba931a1/wal-000000015 (ops 70-74)
I20260812 06:19:40.113142  8551 log.cc:1079] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/a41177872875457dbe2c775fdba931a1/wal-000000016 (ops 75-79)
I20260812 06:19:40.113181  8551 log.cc:1079] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/a41177872875457dbe2c775fdba931a1/wal-000000017 (ops 80-84)
I20260812 06:19:40.113221  8551 log.cc:1079] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/a41177872875457dbe2c775fdba931a1/wal-000000018 (ops 85-89)
I20260812 06:19:40.113260  8551 log.cc:1079] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/a41177872875457dbe2c775fdba931a1/wal-000000019 (ops 90-94)
I20260812 06:19:40.113299  8551 log.cc:1079] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/a41177872875457dbe2c775fdba931a1/wal-000000020 (ops 95-99)
I20260812 06:19:40.113339  8551 log.cc:1079] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/a41177872875457dbe2c775fdba931a1/wal-000000021 (ops 100-104)
I20260812 06:19:40.113377  8551 log.cc:1079] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/a41177872875457dbe2c775fdba931a1/wal-000000022 (ops 105-109)
I20260812 06:19:40.113417  8551 log.cc:1079] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/a41177872875457dbe2c775fdba931a1/wal-000000023 (ops 110-114)
I20260812 06:19:40.113456  8551 log.cc:1079] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/a41177872875457dbe2c775fdba931a1/wal-000000024 (ops 115-119)
I20260812 06:19:40.113493  8551 log.cc:1079] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/a41177872875457dbe2c775fdba931a1/wal-000000025 (ops 120-124)
I20260812 06:19:40.140084  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: LogGCOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.027s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:19:40.140535  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1): perf score=3.181125
I20260812 06:19:40.163403  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.023s	user 0.017s	sys 0.000s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7590,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:40.163890  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1): perf score=2.188937
I20260812 06:19:40.174710  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4026,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:40.175217  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling UndoDeltaBlockGCOp(a41177872875457dbe2c775fdba931a1): 447 bytes on disk
I20260812 06:19:40.175669  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: UndoDeltaBlockGCOp(a41177872875457dbe2c775fdba931a1) 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:40.176196  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling MajorDeltaCompactionOp(a41177872875457dbe2c775fdba931a1): perf score=1.000000
I20260812 06:19:40.411545  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: MajorDeltaCompactionOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.235s	user 0.165s	sys 0.063s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979738,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":411,"lbm_read_time_us":17585,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39125,"lbm_writes_lt_1ms":743,"mutex_wait_us":312,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":10112,"thread_start_us":75,"threads_started":1,"update_count":3500}
I20260812 06:19:40.412137  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1): perf score=18.063937
I20260812 06:19:40.478462  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.066s	user 0.045s	sys 0.019s Metrics: {"bytes_written":20512321,"delete_count":0,"lbm_write_time_us":30476,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:40.479045  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1): perf score=2.188937
I20260812 06:19:40.490813  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4526,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.491354  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling MajorDeltaCompactionOp(a41177872875457dbe2c775fdba931a1): perf score=1.000000
I20260812 06:19:40.663672  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: MajorDeltaCompactionOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.172s	user 0.148s	sys 0.024s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877108,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1421,"lbm_read_time_us":13388,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34112,"lbm_writes_lt_1ms":643,"mutex_wait_us":428,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12160,"update_count":3000}
I20260812 06:19:40.664402  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1): perf score=14.095187
I20260812 06:19:40.717604  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.053s	user 0.041s	sys 0.011s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":23702,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:40.718146  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1): perf score=2.188937
I20260812 06:19:40.729952  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.012s	user 0.001s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4353,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.730432  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling MajorDeltaCompactionOp(a41177872875457dbe2c775fdba931a1): perf score=1.000000
I20260812 06:19:40.890341  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: MajorDeltaCompactionOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.160s	user 0.101s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":861,"lbm_read_time_us":13754,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27864,"lbm_writes_lt_1ms":543,"mutex_wait_us":375,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":2500}
I20260812 06:19:40.890985  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1): perf score=12.110812
I20260812 06:19:40.930325  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.039s	user 0.022s	sys 0.015s Metrics: {"bytes_written":13456166,"delete_count":0,"lbm_write_time_us":17095,"lbm_writes_lt_1ms":331,"reinsert_count":0,"update_count":1640}
I20260812 06:19:40.931039  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1): perf score=1.196750
I20260812 06:19:40.948553  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.017s	user 0.003s	sys 0.008s Metrics: {"bytes_written":2953955,"delete_count":0,"lbm_write_time_us":4848,"lbm_writes_lt_1ms":75,"reinsert_count":0,"update_count":360}
I20260812 06:19:40.949144  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling MajorDeltaCompactionOp(a41177872875457dbe2c775fdba931a1): perf score=1.000000
I20260812 06:19:41.104491  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: MajorDeltaCompactionOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.155s	user 0.098s	sys 0.051s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672249,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":965,"lbm_read_time_us":9717,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25320,"lbm_writes_lt_1ms":443,"mutex_wait_us":267,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2000}
I20260812 06:19:41.105113  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1): perf score=14.095187
I20260812 06:19:41.159684  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.054s	user 0.044s	sys 0.004s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22166,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:41.160251  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1): perf score=2.188937
I20260812 06:19:41.181795  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.021s	user 0.005s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4564,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.182395  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling MajorDeltaCompactionOp(a41177872875457dbe2c775fdba931a1): perf score=1.000000
I20260812 06:19:41.375681  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: MajorDeltaCompactionOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.193s	user 0.112s	sys 0.080s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":158,"lbm_read_time_us":15710,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31132,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":93184,"update_count":2500}
I20260812 06:19:41.376471  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1): perf score=14.095187
I20260812 06:19:41.429188  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.053s	user 0.033s	sys 0.019s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":23605,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:41.429702  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1): perf score=2.188937
I20260812 06:19:41.442158  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4833,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.442628  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling MajorDeltaCompactionOp(a41177872875457dbe2c775fdba931a1): perf score=1.000000
I20260812 06:19:41.628302  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: MajorDeltaCompactionOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.186s	user 0.125s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1306,"lbm_read_time_us":11706,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31375,"lbm_writes_lt_1ms":543,"mutex_wait_us":362,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2500}
I20260812 06:19:41.628971  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1): perf score=14.095187
I20260812 06:19:41.677356  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.048s	user 0.036s	sys 0.011s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20919,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:41.677915  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1): perf score=2.188937
I20260812 06:19:41.690299  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4625,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.690917  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushMRSOp(a41177872875457dbe2c775fdba931a1): perf score=1.000000
I20260812 06:19:41.724576  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushMRSOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.033s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":230,"dirs.run_wall_time_us":1298,"drs_written":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1834,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:41.725359  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling LogGCOp(a41177872875457dbe2c775fdba931a1): free 132571577 bytes of WAL
I20260812 06:19:41.725613  8551 log_reader.cc:385] T a41177872875457dbe2c775fdba931a1: removed 13 log segments from log reader
I20260812 06:19:41.725674  8551 log.cc:1079] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/a41177872875457dbe2c775fdba931a1/wal-000000026 (ops 125-129)
I20260812 06:19:41.725728  8551 log.cc:1079] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/a41177872875457dbe2c775fdba931a1/wal-000000027 (ops 130-134)
I20260812 06:19:41.725785  8551 log.cc:1079] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/a41177872875457dbe2c775fdba931a1/wal-000000028 (ops 135-139)
I20260812 06:19:41.725829  8551 log.cc:1079] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/a41177872875457dbe2c775fdba931a1/wal-000000029 (ops 140-144)
I20260812 06:19:41.725868  8551 log.cc:1079] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/a41177872875457dbe2c775fdba931a1/wal-000000030 (ops 145-149)
I20260812 06:19:41.725907  8551 log.cc:1079] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/a41177872875457dbe2c775fdba931a1/wal-000000031 (ops 150-154)
I20260812 06:19:41.725947  8551 log.cc:1079] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/a41177872875457dbe2c775fdba931a1/wal-000000032 (ops 155-159)
I20260812 06:19:41.725983  8551 log.cc:1079] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/a41177872875457dbe2c775fdba931a1/wal-000000033 (ops 160-164)
I20260812 06:19:41.726022  8551 log.cc:1079] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/a41177872875457dbe2c775fdba931a1/wal-000000034 (ops 165-168)
I20260812 06:19:41.726063  8551 log.cc:1079] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/a41177872875457dbe2c775fdba931a1/wal-000000035 (ops 169-173)
I20260812 06:19:41.726102  8551 log.cc:1079] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/a41177872875457dbe2c775fdba931a1/wal-000000036 (ops 174-178)
I20260812 06:19:41.726141  8551 log.cc:1079] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/a41177872875457dbe2c775fdba931a1/wal-000000037 (ops 179-182)
I20260812 06:19:41.726181  8551 log.cc:1079] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/a41177872875457dbe2c775fdba931a1/wal-000000038 (ops 183-187)
I20260812 06:19:41.758513  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: LogGCOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.033s	user 0.001s	sys 0.031s Metrics: {}
I20260812 06:19:41.759048  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1): perf score=6.157687
I20260812 06:19:41.782841  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.024s	user 0.017s	sys 0.004s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":10082,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:19:41.783324  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling LogGCOp(a41177872875457dbe2c775fdba931a1): free 12017952 bytes of WAL
I20260812 06:19:41.783550  8551 log_reader.cc:385] T a41177872875457dbe2c775fdba931a1: removed 1 log segments from log reader
I20260812 06:19:41.783610  8551 log.cc:1079] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: Deleting log segment in path: /tmp/dist-test-taskkR5e8l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515570820258-8204-0/minicluster-data/ts-0-root/wals/a41177872875457dbe2c775fdba931a1/wal-000000039 (ops 188-192)
I20260812 06:19:41.787421  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: LogGCOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:41.787848  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling MajorDeltaCompactionOp(a41177872875457dbe2c775fdba931a1): perf score=1.000000
I20260812 06:19:41.994388  8204 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.188s	user 1.898s	sys 0.167s
I20260812 06:19:42.027601  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: MajorDeltaCompactionOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.240s	user 0.178s	sys 0.059s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979635,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"lbm_read_time_us":15843,"lbm_reads_lt_1ms":761,"lbm_write_time_us":42222,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"update_count":3500}
I20260812 06:19:42.028183  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1): perf score=14.095187
I20260812 06:19:42.081727  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: FlushDeltaMemStoresOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.053s	user 0.032s	sys 0.020s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":24286,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:42.082436  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling UndoDeltaBlockGCOp(a41177872875457dbe2c775fdba931a1): 493 bytes on disk
I20260812 06:19:42.082880  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: UndoDeltaBlockGCOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:19:42.083835  8620 maintenance_manager.cc:419] P fce499c9f9934385a42513767641973a: Scheduling MajorDeltaCompactionOp(a41177872875457dbe2c775fdba931a1): perf score=1.000000
I20260812 06:19:42.115536  8204 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.121s	user 0.001s	sys 0.000s
I20260812 06:19:42.116101  8204 tablet_server.cc:179] TabletServer@127.8.3.1:0 shutting down...
I20260812 06:19:42.233309  8551 maintenance_manager.cc:643] P fce499c9f9934385a42513767641973a: MajorDeltaCompactionOp(a41177872875457dbe2c775fdba931a1) complete. Timing: real 0.149s	user 0.078s	sys 0.070s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672160,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":432,"lbm_read_time_us":9075,"lbm_reads_lt_1ms":467,"lbm_write_time_us":27159,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":37376,"update_count":2000}
I20260812 06:19:42.234071  8204 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:42.234349  8204 tablet_replica.cc:333] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a: stopping tablet replica
I20260812 06:19:42.234530  8204 raft_consensus.cc:2243] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:42.234719  8204 raft_consensus.cc:2272] T a41177872875457dbe2c775fdba931a1 P fce499c9f9934385a42513767641973a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:42.239339  8204 tablet_server.cc:196] TabletServer@127.8.3.1:0 shutdown complete.
I20260812 06:19:42.273897  8204 master.cc:562] Master@127.8.3.62:38797 shutting down...
I20260812 06:19:42.277271  8204 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 44dce69474b34a1486232dbf9f56b5f8 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:42.277482  8204 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 44dce69474b34a1486232dbf9f56b5f8 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:42.277578  8204 tablet_replica.cc:333] T 00000000000000000000000000000000 P 44dce69474b34a1486232dbf9f56b5f8: stopping tablet replica
I20260812 06:19:42.289846  8204 master.cc:584] Master@127.8.3.62:38797 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5833 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11552 ms total)

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