[==========] 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:36.997651  8787 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.8.148.254:43389
I20260812 06:19:36.998667  8787 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:36.999277  8787 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:37.005620  8798 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:37.005676  8787 server_base.cc:1061] running on GCE node
W20260812 06:19:37.005623  8796 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:37.005892  8802 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:37.006379  8787 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:37.006474  8787 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:37.006518  8787 hybrid_clock.cc:648] HybridClock initialized: now 1786515577006515 us; error 0 us; skew 500 ppm
I20260812 06:19:37.008407  8787 webserver.cc:533] Webserver started at http://127.8.148.254:35029/ using document root <none> and password file <none>
I20260812 06:19:37.008952  8787 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:37.009032  8787 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:37.009258  8787 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:37.010934  8787 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/master-0-root/instance:
uuid: "bb1e302ef81648bc8de1da19308392b4"
format_stamp: "Formatted at 2026-08-12 06:19:37 on dist-test-slave-nj21"
I20260812 06:19:37.014473  8787 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:19:37.016546  8815 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:37.017481  8787 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:37.017581  8787 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/master-0-root
uuid: "bb1e302ef81648bc8de1da19308392b4"
format_stamp: "Formatted at 2026-08-12 06:19:37 on dist-test-slave-nj21"
I20260812 06:19:37.017673  8787 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-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:37.034927  8787 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:37.035588  8787 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:37.035772  8787 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:37.043121  8902 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.148.254:43389 every 8 connection(s)
I20260812 06:19:37.043124  8787 rpc_server.cc:307] RPC server started. Bound to: 127.8.148.254:43389
I20260812 06:19:37.045431  8904 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:37.051015  8904 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P bb1e302ef81648bc8de1da19308392b4: Bootstrap starting.
I20260812 06:19:37.053412  8904 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P bb1e302ef81648bc8de1da19308392b4: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:37.054319  8904 log.cc:826] T 00000000000000000000000000000000 P bb1e302ef81648bc8de1da19308392b4: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:37.056111  8904 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P bb1e302ef81648bc8de1da19308392b4: No bootstrap required, opened a new log
I20260812 06:19:37.058893  8904 raft_consensus.cc:359] T 00000000000000000000000000000000 P bb1e302ef81648bc8de1da19308392b4 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bb1e302ef81648bc8de1da19308392b4" member_type: VOTER }
I20260812 06:19:37.059060  8904 raft_consensus.cc:385] T 00000000000000000000000000000000 P bb1e302ef81648bc8de1da19308392b4 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:37.059120  8904 raft_consensus.cc:740] T 00000000000000000000000000000000 P bb1e302ef81648bc8de1da19308392b4 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: bb1e302ef81648bc8de1da19308392b4, State: Initialized, Role: FOLLOWER
I20260812 06:19:37.059813  8904 consensus_queue.cc:260] T 00000000000000000000000000000000 P bb1e302ef81648bc8de1da19308392b4 [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: "bb1e302ef81648bc8de1da19308392b4" member_type: VOTER }
I20260812 06:19:37.059966  8904 raft_consensus.cc:399] T 00000000000000000000000000000000 P bb1e302ef81648bc8de1da19308392b4 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:37.060067  8904 raft_consensus.cc:493] T 00000000000000000000000000000000 P bb1e302ef81648bc8de1da19308392b4 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:37.060190  8904 raft_consensus.cc:3060] T 00000000000000000000000000000000 P bb1e302ef81648bc8de1da19308392b4 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:37.060961  8904 raft_consensus.cc:515] T 00000000000000000000000000000000 P bb1e302ef81648bc8de1da19308392b4 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bb1e302ef81648bc8de1da19308392b4" member_type: VOTER }
I20260812 06:19:37.061349  8904 leader_election.cc:304] T 00000000000000000000000000000000 P bb1e302ef81648bc8de1da19308392b4 [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: bb1e302ef81648bc8de1da19308392b4; no voters: 
I20260812 06:19:37.061626  8904 leader_election.cc:290] T 00000000000000000000000000000000 P bb1e302ef81648bc8de1da19308392b4 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:37.061744  8909 raft_consensus.cc:2804] T 00000000000000000000000000000000 P bb1e302ef81648bc8de1da19308392b4 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:37.061976  8909 raft_consensus.cc:697] T 00000000000000000000000000000000 P bb1e302ef81648bc8de1da19308392b4 [term 1 LEADER]: Becoming Leader. State: Replica: bb1e302ef81648bc8de1da19308392b4, State: Running, Role: LEADER
I20260812 06:19:37.062361  8909 consensus_queue.cc:237] T 00000000000000000000000000000000 P bb1e302ef81648bc8de1da19308392b4 [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: "bb1e302ef81648bc8de1da19308392b4" member_type: VOTER }
I20260812 06:19:37.062579  8904 sys_catalog.cc:565] T 00000000000000000000000000000000 P bb1e302ef81648bc8de1da19308392b4 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:37.064224  8911 sys_catalog.cc:455] T 00000000000000000000000000000000 P bb1e302ef81648bc8de1da19308392b4 [sys.catalog]: SysCatalogTable state changed. Reason: New leader bb1e302ef81648bc8de1da19308392b4. Latest consensus state: current_term: 1 leader_uuid: "bb1e302ef81648bc8de1da19308392b4" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bb1e302ef81648bc8de1da19308392b4" member_type: VOTER } }
I20260812 06:19:37.064211  8910 sys_catalog.cc:455] T 00000000000000000000000000000000 P bb1e302ef81648bc8de1da19308392b4 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "bb1e302ef81648bc8de1da19308392b4" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bb1e302ef81648bc8de1da19308392b4" member_type: VOTER } }
I20260812 06:19:37.064363  8911 sys_catalog.cc:458] T 00000000000000000000000000000000 P bb1e302ef81648bc8de1da19308392b4 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:37.064363  8910 sys_catalog.cc:458] T 00000000000000000000000000000000 P bb1e302ef81648bc8de1da19308392b4 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:37.064692  8787 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:37.064734  8939 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:37.067409  8939 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:37.071655  8939 catalog_manager.cc:1383] Generated new cluster ID: e644c0bd4b2047558b42f618591d6a84
I20260812 06:19:37.071738  8939 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:37.090999  8939 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:37.091912  8939 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:37.100538  8939 catalog_manager.cc:6092] T 00000000000000000000000000000000 P bb1e302ef81648bc8de1da19308392b4: Generated new TSK 0
I20260812 06:19:37.101132  8939 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:37.129647  8787 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:37.132655  8948 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:37.132750  8947 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:37.132773  8953 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:37.133080  8787 server_base.cc:1061] running on GCE node
I20260812 06:19:37.133267  8787 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:37.133306  8787 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:37.133320  8787 hybrid_clock.cc:648] HybridClock initialized: now 1786515577133321 us; error 0 us; skew 500 ppm
I20260812 06:19:37.134140  8787 webserver.cc:533] Webserver started at http://127.8.148.193:36787/ using document root <none> and password file <none>
I20260812 06:19:37.134301  8787 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:37.134353  8787 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:37.134430  8787 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:37.134822  8787 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/instance:
uuid: "f5165620d7f340ea9f47e9622a919d62"
format_stamp: "Formatted at 2026-08-12 06:19:37 on dist-test-slave-nj21"
I20260812 06:19:37.136312  8787 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:37.137247  8963 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:37.137491  8787 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:37.137562  8787 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root
uuid: "f5165620d7f340ea9f47e9622a919d62"
format_stamp: "Formatted at 2026-08-12 06:19:37 on dist-test-slave-nj21"
I20260812 06:19:37.137630  8787 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-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:37.149179  8787 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:37.149602  8787 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:37.150059  8787 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:37.150885  8787 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:37.150936  8787 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:37.150990  8787 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:37.151015  8787 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:37.157166  8787 rpc_server.cc:307] RPC server started. Bound to: 127.8.148.193:34643
I20260812 06:19:37.157341  9073 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.148.193:34643 every 8 connection(s)
I20260812 06:19:37.171324  9076 heartbeater.cc:344] Connected to a master server at 127.8.148.254:43389
I20260812 06:19:37.171592  9076 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:37.172142  9076 heartbeater.cc:507] Master 127.8.148.254:43389 requested a full tablet report, sending...
I20260812 06:19:37.173696  8849 ts_manager.cc:194] Registered new tserver with Master: f5165620d7f340ea9f47e9622a919d62 (127.8.148.193:34643)
I20260812 06:19:37.174480  8787 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.016669975s
I20260812 06:19:37.175053  8849 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:40296
I20260812 06:19:37.184006  8849 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:40300:
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:37.198210  9008 tablet_service.cc:1511] Processing CreateTablet for tablet 030612d0399648e0b8adb7d276eebedb (DEFAULT_TABLE table=heavy-update-compaction-test [id=677d9fbe5b914a81864b62259a9a5317]), partition=
I20260812 06:19:37.198736  9008 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 030612d0399648e0b8adb7d276eebedb. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:37.200981  9098 tablet_bootstrap.cc:492] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Bootstrap starting.
I20260812 06:19:37.202339  9098 tablet_bootstrap.cc:654] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:37.203449  9098 tablet_bootstrap.cc:492] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: No bootstrap required, opened a new log
I20260812 06:19:37.203531  9098 ts_tablet_manager.cc:1403] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:37.203998  9098 raft_consensus.cc:359] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f5165620d7f340ea9f47e9622a919d62" member_type: VOTER last_known_addr { host: "127.8.148.193" port: 34643 } }
I20260812 06:19:37.204101  9098 raft_consensus.cc:385] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:37.204123  9098 raft_consensus.cc:740] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f5165620d7f340ea9f47e9622a919d62, State: Initialized, Role: FOLLOWER
I20260812 06:19:37.204237  9098 consensus_queue.cc:260] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62 [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: "f5165620d7f340ea9f47e9622a919d62" member_type: VOTER last_known_addr { host: "127.8.148.193" port: 34643 } }
I20260812 06:19:37.204306  9098 raft_consensus.cc:399] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:37.204344  9098 raft_consensus.cc:493] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:37.204392  9098 raft_consensus.cc:3060] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:37.205068  9098 raft_consensus.cc:515] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f5165620d7f340ea9f47e9622a919d62" member_type: VOTER last_known_addr { host: "127.8.148.193" port: 34643 } }
I20260812 06:19:37.205188  9098 leader_election.cc:304] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62 [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: f5165620d7f340ea9f47e9622a919d62; no voters: 
I20260812 06:19:37.205368  9098 leader_election.cc:290] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:37.205469  9101 raft_consensus.cc:2804] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:37.205627  9101 raft_consensus.cc:697] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62 [term 1 LEADER]: Becoming Leader. State: Replica: f5165620d7f340ea9f47e9622a919d62, State: Running, Role: LEADER
I20260812 06:19:37.205688  9098 ts_tablet_manager.cc:1434] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:37.205750  9101 consensus_queue.cc:237] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62 [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: "f5165620d7f340ea9f47e9622a919d62" member_type: VOTER last_known_addr { host: "127.8.148.193" port: 34643 } }
I20260812 06:19:37.206080  9076 heartbeater.cc:499] Master 127.8.148.254:43389 was elected leader, sending a full tablet report...
I20260812 06:19:37.208892  8849 catalog_manager.cc:5719] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62 reported cstate change: term changed from 0 to 1, leader changed from <none> to f5165620d7f340ea9f47e9622a919d62 (127.8.148.193). New cstate: current_term: 1 leader_uuid: "f5165620d7f340ea9f47e9622a919d62" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f5165620d7f340ea9f47e9622a919d62" member_type: VOTER last_known_addr { host: "127.8.148.193" port: 34643 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:37.274295  8787 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.024s	sys 0.004s
I20260812 06:19:37.408265  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushMRSOp(030612d0399648e0b8adb7d276eebedb): perf score=19.054940
I20260812 06:19:37.586927  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushMRSOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.178s	user 0.138s	sys 0.032s Metrics: {"bytes_written":14071526,"cfile_init":1,"compiler_manager_pool.queue_time_us":212,"delete_count":0,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":235,"dirs.run_wall_time_us":825,"drs_written":1,"lbm_read_time_us":84,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43709,"lbm_writes_lt_1ms":800,"mutex_wait_us":1252,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":194816,"thread_start_us":112,"threads_started":1,"update_count":1715}
I20260812 06:19:37.588327  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling UndoDeltaBlockGCOp(030612d0399648e0b8adb7d276eebedb): 16411395 bytes on disk
I20260812 06:19:37.588932  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: UndoDeltaBlockGCOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:19:37.589354  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=2.188937
I20260812 06:19:37.604315  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3815488,"delete_count":0,"lbm_write_time_us":5565,"lbm_writes_lt_1ms":96,"reinsert_count":0,"update_count":465}
I20260812 06:19:37.604799  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling LogGCOp(030612d0399648e0b8adb7d276eebedb): free 20743880 bytes of WAL
I20260812 06:19:37.605106  8969 log_reader.cc:385] T 030612d0399648e0b8adb7d276eebedb: removed 2 log segments from log reader
I20260812 06:19:37.605187  8969 log.cc:1079] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/030612d0399648e0b8adb7d276eebedb/wal-000000001 (ops 1-6)
I20260812 06:19:37.605255  8969 log.cc:1079] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/030612d0399648e0b8adb7d276eebedb/wal-000000002 (ops 7-11)
I20260812 06:19:37.610365  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: LogGCOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:19:37.610679  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=1.196750
I20260812 06:19:37.619882  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.009s	user 0.005s	sys 0.004s Metrics: {"bytes_written":2625754,"delete_count":0,"lbm_write_time_us":3375,"lbm_writes_lt_1ms":67,"reinsert_count":0,"update_count":320}
I20260812 06:19:37.620285  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb): perf score=1.000000
I20260812 06:19:37.795518  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.175s	user 0.113s	sys 0.061s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774768,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":464,"lbm_read_time_us":9548,"lbm_reads_lt_1ms":569,"lbm_write_time_us":31074,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"thread_start_us":232,"threads_started":5,"update_count":2500}
I20260812 06:19:37.795938  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=10.126437
I20260812 06:19:37.841027  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.045s	user 0.021s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14093,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:37.841583  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=2.188937
I20260812 06:19:37.851740  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3603,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:37.852242  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb): perf score=1.000000
I20260812 06:19:37.977186  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.125s	user 0.092s	sys 0.030s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":145,"lbm_read_time_us":7419,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23723,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:37.977644  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=10.126437
I20260812 06:19:38.017215  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.039s	user 0.019s	sys 0.017s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16278,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:38.017664  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb): perf score=1.000000
I20260812 06:19:38.117944  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.100s	user 0.072s	sys 0.028s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569747,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1195,"lbm_read_time_us":5447,"lbm_reads_lt_1ms":363,"lbm_write_time_us":16833,"lbm_writes_lt_1ms":343,"mutex_wait_us":291,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:19:38.118436  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=10.126437
I20260812 06:19:38.150875  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.032s	user 0.017s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":13938,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:38.151419  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb): perf score=1.000000
I20260812 06:19:38.264430  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.113s	user 0.092s	sys 0.020s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569748,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":815,"lbm_read_time_us":6714,"lbm_reads_lt_1ms":367,"lbm_write_time_us":18485,"lbm_writes_lt_1ms":343,"mutex_wait_us":269,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":104576,"update_count":1500}
I20260812 06:19:38.264928  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=10.126437
I20260812 06:19:38.298388  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.033s	user 0.010s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12357,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:38.298842  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=2.188937
I20260812 06:19:38.309141  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3825,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.309732  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb): perf score=1.000000
I20260812 06:19:38.427564  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.118s	user 0.080s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":184,"lbm_read_time_us":7855,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23556,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:38.428097  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=10.126437
I20260812 06:19:38.471735  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.043s	user 0.017s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12037,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:38.472222  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=2.188937
I20260812 06:19:38.487147  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5479,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.487643  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb): perf score=1.000000
I20260812 06:19:38.600744  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.113s	user 0.084s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":221,"lbm_read_time_us":7966,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21377,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2000}
I20260812 06:19:38.601233  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=10.126437
I20260812 06:19:38.644090  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.043s	user 0.031s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13190,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:38.644569  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=2.188937
I20260812 06:19:38.654505  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3803,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.654915  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb): perf score=1.000000
I20260812 06:19:38.791034  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.136s	user 0.094s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":991,"lbm_read_time_us":9521,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22687,"lbm_writes_lt_1ms":443,"mutex_wait_us":271,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:38.791522  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=10.126437
I20260812 06:19:38.832234  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.041s	user 0.013s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12545,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":1500}
I20260812 06:19:38.832799  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=2.188937
I20260812 06:19:38.842890  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3786,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.843454  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushMRSOp(030612d0399648e0b8adb7d276eebedb): perf score=1.000000
I20260812 06:19:38.871912  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushMRSOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.028s	user 0.025s	sys 0.003s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":215,"dirs.run_wall_time_us":1057,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1390,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:38.872732  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling LogGCOp(030612d0399648e0b8adb7d276eebedb): free 128867407 bytes of WAL
I20260812 06:19:38.872967  8969 log_reader.cc:385] T 030612d0399648e0b8adb7d276eebedb: removed 13 log segments from log reader
I20260812 06:19:38.873024  8969 log.cc:1079] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/030612d0399648e0b8adb7d276eebedb/wal-000000003 (ops 12-16)
I20260812 06:19:38.873071  8969 log.cc:1079] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/030612d0399648e0b8adb7d276eebedb/wal-000000004 (ops 17-21)
I20260812 06:19:38.873106  8969 log.cc:1079] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/030612d0399648e0b8adb7d276eebedb/wal-000000005 (ops 22-26)
I20260812 06:19:38.873133  8969 log.cc:1079] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/030612d0399648e0b8adb7d276eebedb/wal-000000006 (ops 27-30)
I20260812 06:19:38.873160  8969 log.cc:1079] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/030612d0399648e0b8adb7d276eebedb/wal-000000007 (ops 31-35)
I20260812 06:19:38.873190  8969 log.cc:1079] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/030612d0399648e0b8adb7d276eebedb/wal-000000008 (ops 36-40)
I20260812 06:19:38.873224  8969 log.cc:1079] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/030612d0399648e0b8adb7d276eebedb/wal-000000009 (ops 41-44)
I20260812 06:19:38.873251  8969 log.cc:1079] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/030612d0399648e0b8adb7d276eebedb/wal-000000010 (ops 45-49)
I20260812 06:19:38.873279  8969 log.cc:1079] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/030612d0399648e0b8adb7d276eebedb/wal-000000011 (ops 50-54)
I20260812 06:19:38.873306  8969 log.cc:1079] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/030612d0399648e0b8adb7d276eebedb/wal-000000012 (ops 55-59)
I20260812 06:19:38.873344  8969 log.cc:1079] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/030612d0399648e0b8adb7d276eebedb/wal-000000013 (ops 60-64)
I20260812 06:19:38.873377  8969 log.cc:1079] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/030612d0399648e0b8adb7d276eebedb/wal-000000014 (ops 65-68)
I20260812 06:19:38.873409  8969 log.cc:1079] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/030612d0399648e0b8adb7d276eebedb/wal-000000015 (ops 69-73)
I20260812 06:19:38.897527  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: LogGCOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.025s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:19:38.897962  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling UndoDeltaBlockGCOp(030612d0399648e0b8adb7d276eebedb): 482 bytes on disk
I20260812 06:19:38.898677  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: UndoDeltaBlockGCOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:19:38.899176  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=3.181125
I20260812 06:19:38.924074  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.025s	user 0.017s	sys 0.007s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":6524,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:38.924564  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=2.188937
I20260812 06:19:38.934931  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3833,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:38.935370  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb): perf score=1.000000
I20260812 06:19:39.122946  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.187s	user 0.138s	sys 0.040s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877325,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":546,"lbm_read_time_us":14041,"lbm_reads_lt_1ms":674,"lbm_write_time_us":28531,"lbm_writes_lt_1ms":643,"mutex_wait_us":36,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8704,"thread_start_us":80,"threads_started":1,"update_count":3000}
I20260812 06:19:39.123484  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=14.095187
I20260812 06:19:39.178273  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.055s	user 0.024s	sys 0.026s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":19655,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:39.178793  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=2.188937
I20260812 06:19:39.188912  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3798,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:39.189354  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb): perf score=1.000000
I20260812 06:19:39.350102  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.161s	user 0.109s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":639,"lbm_read_time_us":11365,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26921,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:19:39.351251  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=10.126437
I20260812 06:19:39.385079  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.034s	user 0.021s	sys 0.011s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":13305,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:39.385828  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=2.188937
I20260812 06:19:39.405859  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.017s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6437,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:39.406414  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb): perf score=1.000000
I20260812 06:19:39.527746  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.121s	user 0.097s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":243,"lbm_read_time_us":8672,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23055,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:19:39.528260  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=10.126437
I20260812 06:19:39.562845  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.034s	user 0.019s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14630,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:39.563371  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=2.188937
I20260812 06:19:39.573817  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3745,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:39.574622  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb): perf score=1.000000
I20260812 06:19:39.700495  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.126s	user 0.102s	sys 0.023s 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":341,"lbm_read_time_us":9497,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21136,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":113280,"update_count":2000}
I20260812 06:19:39.701045  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=10.126437
I20260812 06:19:39.739653  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.038s	user 0.025s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13531,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:39.740231  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=2.188937
I20260812 06:19:39.750284  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3655,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:39.750712  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb): perf score=1.000000
I20260812 06:19:39.874460  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.124s	user 0.091s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":745,"lbm_read_time_us":9980,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21492,"lbm_writes_lt_1ms":443,"mutex_wait_us":85,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:39.874994  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=10.126437
I20260812 06:19:39.920759  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.046s	user 0.027s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18339,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:39.921278  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=2.188937
I20260812 06:19:39.931350  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3814,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:39.931814  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb): perf score=1.000000
I20260812 06:19:40.070186  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.138s	user 0.101s	sys 0.037s 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":193,"lbm_read_time_us":10303,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22956,"lbm_writes_lt_1ms":443,"mutex_wait_us":54,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:19:40.070726  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=10.126437
I20260812 06:19:40.107340  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.036s	user 0.022s	sys 0.011s Metrics: {"bytes_written":12307494,"delete_count":0,"lbm_write_time_us":16471,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:40.107908  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=2.188937
I20260812 06:19:40.119490  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3746,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.119972  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb): perf score=1.000000
I20260812 06:19:40.238329  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.118s	user 0.086s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672280,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":138,"lbm_read_time_us":7505,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23512,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:19:40.238901  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=10.126437
I20260812 06:19:40.269936  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.031s	user 0.024s	sys 0.004s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13110,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:40.270483  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushMRSOp(030612d0399648e0b8adb7d276eebedb): perf score=1.000000
I20260812 06:19:40.323372  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushMRSOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.053s	user 0.029s	sys 0.004s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":184,"dirs.run_wall_time_us":828,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1544,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:40.324185  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling LogGCOp(030612d0399648e0b8adb7d276eebedb): free 124257315 bytes of WAL
I20260812 06:19:40.324427  8969 log_reader.cc:385] T 030612d0399648e0b8adb7d276eebedb: removed 12 log segments from log reader
I20260812 06:19:40.324493  8969 log.cc:1079] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/030612d0399648e0b8adb7d276eebedb/wal-000000016 (ops 74-78)
I20260812 06:19:40.324534  8969 log.cc:1079] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/030612d0399648e0b8adb7d276eebedb/wal-000000017 (ops 79-83)
I20260812 06:19:40.324565  8969 log.cc:1079] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/030612d0399648e0b8adb7d276eebedb/wal-000000018 (ops 84-88)
I20260812 06:19:40.324599  8969 log.cc:1079] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/030612d0399648e0b8adb7d276eebedb/wal-000000019 (ops 89-93)
I20260812 06:19:40.324627  8969 log.cc:1079] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/030612d0399648e0b8adb7d276eebedb/wal-000000020 (ops 94-98)
I20260812 06:19:40.324654  8969 log.cc:1079] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/030612d0399648e0b8adb7d276eebedb/wal-000000021 (ops 99-103)
I20260812 06:19:40.324681  8969 log.cc:1079] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/030612d0399648e0b8adb7d276eebedb/wal-000000022 (ops 104-108)
I20260812 06:19:40.324707  8969 log.cc:1079] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/030612d0399648e0b8adb7d276eebedb/wal-000000023 (ops 109-113)
I20260812 06:19:40.324740  8969 log.cc:1079] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/030612d0399648e0b8adb7d276eebedb/wal-000000024 (ops 114-118)
I20260812 06:19:40.324767  8969 log.cc:1079] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/030612d0399648e0b8adb7d276eebedb/wal-000000025 (ops 119-123)
I20260812 06:19:40.324788  8969 log.cc:1079] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/030612d0399648e0b8adb7d276eebedb/wal-000000026 (ops 124-128)
I20260812 06:19:40.324824  8969 log.cc:1079] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/030612d0399648e0b8adb7d276eebedb/wal-000000027 (ops 129-132)
I20260812 06:19:40.350778  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: LogGCOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.026s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:19:40.351269  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=7.149875
I20260812 06:19:40.378487  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.027s	user 0.014s	sys 0.011s Metrics: {"bytes_written":8615324,"delete_count":0,"lbm_write_time_us":11343,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:19:40.379019  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=2.188937
I20260812 06:19:40.389199  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3711,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:40.389745  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling UndoDeltaBlockGCOp(030612d0399648e0b8adb7d276eebedb): 482 bytes on disk
I20260812 06:19:40.390211  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: UndoDeltaBlockGCOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:19:40.390897  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb): perf score=1.000000
I20260812 06:19:40.543995  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.153s	user 0.106s	sys 0.044s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877214,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":588,"lbm_read_time_us":9846,"lbm_reads_lt_1ms":665,"lbm_write_time_us":28125,"lbm_writes_lt_1ms":643,"mutex_wait_us":305,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":79,"threads_started":1,"update_count":3000}
I20260812 06:19:40.544634  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=14.095187
I20260812 06:19:40.591519  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.046s	user 0.023s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20309,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:40.592082  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=2.188937
I20260812 06:19:40.609833  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.018s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5396,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.610335  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb): perf score=1.000000
I20260812 06:19:40.756307  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.146s	user 0.104s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":357,"lbm_read_time_us":10206,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27320,"lbm_writes_lt_1ms":543,"mutex_wait_us":97,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:40.756923  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=14.095187
I20260812 06:19:40.803889  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.047s	user 0.031s	sys 0.016s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20533,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:40.804458  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb): perf score=1.000000
I20260812 06:19:40.936972  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.132s	user 0.103s	sys 0.028s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672156,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":210,"lbm_read_time_us":8946,"lbm_reads_lt_1ms":467,"lbm_write_time_us":22982,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:19:40.937606  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=10.126437
I20260812 06:19:40.967154  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.029s	user 0.011s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12627,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:40.967763  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=2.188937
I20260812 06:19:40.979640  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4505,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.980278  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb): perf score=1.000000
I20260812 06:19:41.097350  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.117s	user 0.102s	sys 0.014s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":259,"lbm_read_time_us":9457,"lbm_reads_lt_1ms":464,"lbm_write_time_us":20939,"lbm_writes_lt_1ms":443,"mutex_wait_us":31,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4608,"update_count":2000}
I20260812 06:19:41.098016  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=10.126437
I20260812 06:19:41.138516  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.040s	user 0.017s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12986,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:41.139123  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=2.188937
I20260812 06:19:41.153952  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5321,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.154525  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb): perf score=1.000000
I20260812 06:19:41.263355  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.109s	user 0.101s	sys 0.008s 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":162,"lbm_read_time_us":7940,"lbm_reads_lt_1ms":472,"lbm_write_time_us":19961,"lbm_writes_lt_1ms":443,"mutex_wait_us":35,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":2000}
I20260812 06:19:41.264053  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=10.126437
I20260812 06:19:41.303570  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.039s	user 0.012s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12806,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:41.304199  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=2.188937
I20260812 06:19:41.316102  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4179,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.316721  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb): perf score=1.000000
I20260812 06:19:41.427408  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.110s	user 0.082s	sys 0.028s 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":732,"lbm_read_time_us":7055,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21643,"lbm_writes_lt_1ms":443,"mutex_wait_us":237,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:19:41.427960  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=10.126437
I20260812 06:19:41.468259  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.040s	user 0.027s	sys 0.010s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12855,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:41.468845  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=2.188937
I20260812 06:19:41.483986  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.015s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5591,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.484560  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb): perf score=1.000000
I20260812 06:19:41.629635  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.145s	user 0.104s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":847,"lbm_read_time_us":10402,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22204,"lbm_writes_lt_1ms":443,"mutex_wait_us":355,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:41.630329  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=10.126437
I20260812 06:19:41.668071  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.038s	user 0.015s	sys 0.016s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":12950,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:41.668560  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=2.188937
I20260812 06:19:41.684008  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.015s	user 0.008s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5786,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.684789  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushMRSOp(030612d0399648e0b8adb7d276eebedb): perf score=1.000000
I20260812 06:19:41.717742  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushMRSOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.033s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":176,"dirs.run_wall_time_us":1188,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1575,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:41.718432  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling LogGCOp(030612d0399648e0b8adb7d276eebedb): free 133477702 bytes of WAL
I20260812 06:19:41.718654  8969 log_reader.cc:385] T 030612d0399648e0b8adb7d276eebedb: removed 13 log segments from log reader
I20260812 06:19:41.718700  8969 log.cc:1079] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/030612d0399648e0b8adb7d276eebedb/wal-000000028 (ops 133-137)
I20260812 06:19:41.718729  8969 log.cc:1079] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/030612d0399648e0b8adb7d276eebedb/wal-000000029 (ops 138-142)
I20260812 06:19:41.718758  8969 log.cc:1079] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/030612d0399648e0b8adb7d276eebedb/wal-000000030 (ops 143-147)
I20260812 06:19:41.718798  8969 log.cc:1079] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/030612d0399648e0b8adb7d276eebedb/wal-000000031 (ops 148-152)
I20260812 06:19:41.718832  8969 log.cc:1079] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/030612d0399648e0b8adb7d276eebedb/wal-000000032 (ops 153-157)
I20260812 06:19:41.718863  8969 log.cc:1079] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/030612d0399648e0b8adb7d276eebedb/wal-000000033 (ops 158-162)
I20260812 06:19:41.718896  8969 log.cc:1079] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/030612d0399648e0b8adb7d276eebedb/wal-000000034 (ops 163-167)
I20260812 06:19:41.718927  8969 log.cc:1079] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/030612d0399648e0b8adb7d276eebedb/wal-000000035 (ops 168-172)
I20260812 06:19:41.718961  8969 log.cc:1079] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/030612d0399648e0b8adb7d276eebedb/wal-000000036 (ops 173-177)
I20260812 06:19:41.718992  8969 log.cc:1079] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/030612d0399648e0b8adb7d276eebedb/wal-000000037 (ops 178-182)
I20260812 06:19:41.719025  8969 log.cc:1079] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/030612d0399648e0b8adb7d276eebedb/wal-000000038 (ops 183-187)
I20260812 06:19:41.719058  8969 log.cc:1079] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/030612d0399648e0b8adb7d276eebedb/wal-000000039 (ops 188-192)
I20260812 06:19:41.719090  8969 log.cc:1079] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/030612d0399648e0b8adb7d276eebedb/wal-000000040 (ops 193-197)
I20260812 06:19:41.744510  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: LogGCOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:19:41.744964  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=3.181125
I20260812 06:19:41.767823  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.023s	user 0.017s	sys 0.006s Metrics: {"bytes_written":5005191,"delete_count":0,"lbm_write_time_us":6696,"lbm_writes_lt_1ms":125,"reinsert_count":0,"update_count":610}
I20260812 06:19:41.768270  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling UndoDeltaBlockGCOp(030612d0399648e0b8adb7d276eebedb): 482 bytes on disk
I20260812 06:19:41.768671  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: UndoDeltaBlockGCOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:19:41.769170  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb): perf score=2.188937
I20260812 06:19:41.777514  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: FlushDeltaMemStoresOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.008s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3200105,"delete_count":0,"lbm_write_time_us":2885,"lbm_writes_lt_1ms":81,"reinsert_count":0,"update_count":390}
I20260812 06:19:41.777912  9077 maintenance_manager.cc:419] P f5165620d7f340ea9f47e9622a919d62: Scheduling MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb): perf score=1.000000
I20260812 06:19:41.831197  8787 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.557s	user 1.654s	sys 0.154s
I20260812 06:19:41.925093  8787 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.093s	user 0.002s	sys 0.000s
I20260812 06:19:41.925714  8787 tablet_server.cc:179] TabletServer@127.8.148.193:0 shutting down...
I20260812 06:19:41.947336  8969 maintenance_manager.cc:643] P f5165620d7f340ea9f47e9622a919d62: MajorDeltaCompactionOp(030612d0399648e0b8adb7d276eebedb) complete. Timing: real 0.169s	user 0.121s	sys 0.048s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877319,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":457,"lbm_read_time_us":12424,"lbm_reads_lt_1ms":670,"lbm_write_time_us":25283,"lbm_writes_lt_1ms":643,"mutex_wait_us":67,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":72960,"thread_start_us":84,"threads_started":1,"update_count":3000}
I20260812 06:19:41.948599  8787 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:41.948983  8787 tablet_replica.cc:333] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62: stopping tablet replica
I20260812 06:19:41.949213  8787 raft_consensus.cc:2243] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:41.949432  8787 raft_consensus.cc:2272] T 030612d0399648e0b8adb7d276eebedb P f5165620d7f340ea9f47e9622a919d62 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:41.964871  8787 tablet_server.cc:196] TabletServer@127.8.148.193:0 shutdown complete.
I20260812 06:19:41.998436  8787 master.cc:562] Master@127.8.148.254:43389 shutting down...
I20260812 06:19:42.001871  8787 raft_consensus.cc:2243] T 00000000000000000000000000000000 P bb1e302ef81648bc8de1da19308392b4 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:42.002056  8787 raft_consensus.cc:2272] T 00000000000000000000000000000000 P bb1e302ef81648bc8de1da19308392b4 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:42.002131  8787 tablet_replica.cc:333] T 00000000000000000000000000000000 P bb1e302ef81648bc8de1da19308392b4: stopping tablet replica
I20260812 06:19:42.014308  8787 master.cc:584] Master@127.8.148.254:43389 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5086 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:42.094409  8787 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.8.148.254:41287
I20260812 06:19:42.094794  8787 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:19:42.096748  8787 server_base.cc:1061] running on GCE node
W20260812 06:19:42.096783  9130 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:42.096861  9140 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:42.096879  9135 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:42.097158  8787 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:42.097201  8787 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:42.097215  8787 hybrid_clock.cc:648] HybridClock initialized: now 1786515582097216 us; error 0 us; skew 500 ppm
I20260812 06:19:42.098028  8787 webserver.cc:533] Webserver started at http://127.8.148.254:35651/ using document root <none> and password file <none>
I20260812 06:19:42.098174  8787 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:42.098217  8787 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:42.098271  8787 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:42.098610  8787 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/master-0-root/instance:
uuid: "d257d8acd2874625b68ce11143144e70"
format_stamp: "Formatted at 2026-08-12 06:19:42 on dist-test-slave-nj21"
I20260812 06:19:42.100107  8787 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:42.101048  9147 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:42.101277  8787 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:42.101346  8787 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/master-0-root
uuid: "d257d8acd2874625b68ce11143144e70"
format_stamp: "Formatted at 2026-08-12 06:19:42 on dist-test-slave-nj21"
I20260812 06:19:42.101421  8787 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-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:42.118906  8787 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:42.119316  8787 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:42.123394  8787 rpc_server.cc:307] RPC server started. Bound to: 127.8.148.254:41287
I20260812 06:19:42.126046  9233 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.148.254:41287 every 8 connection(s)
I20260812 06:19:42.126524  9236 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:42.128378  9236 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d257d8acd2874625b68ce11143144e70: Bootstrap starting.
I20260812 06:19:42.129113  9236 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P d257d8acd2874625b68ce11143144e70: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:42.130079  9236 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d257d8acd2874625b68ce11143144e70: No bootstrap required, opened a new log
I20260812 06:19:42.130440  9236 raft_consensus.cc:359] T 00000000000000000000000000000000 P d257d8acd2874625b68ce11143144e70 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d257d8acd2874625b68ce11143144e70" member_type: VOTER }
I20260812 06:19:42.130527  9236 raft_consensus.cc:385] T 00000000000000000000000000000000 P d257d8acd2874625b68ce11143144e70 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:42.130548  9236 raft_consensus.cc:740] T 00000000000000000000000000000000 P d257d8acd2874625b68ce11143144e70 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d257d8acd2874625b68ce11143144e70, State: Initialized, Role: FOLLOWER
I20260812 06:19:42.130661  9236 consensus_queue.cc:260] T 00000000000000000000000000000000 P d257d8acd2874625b68ce11143144e70 [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: "d257d8acd2874625b68ce11143144e70" member_type: VOTER }
I20260812 06:19:42.130728  9236 raft_consensus.cc:399] T 00000000000000000000000000000000 P d257d8acd2874625b68ce11143144e70 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:42.130749  9236 raft_consensus.cc:493] T 00000000000000000000000000000000 P d257d8acd2874625b68ce11143144e70 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:42.130785  9236 raft_consensus.cc:3060] T 00000000000000000000000000000000 P d257d8acd2874625b68ce11143144e70 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:42.131413  9236 raft_consensus.cc:515] T 00000000000000000000000000000000 P d257d8acd2874625b68ce11143144e70 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d257d8acd2874625b68ce11143144e70" member_type: VOTER }
I20260812 06:19:42.131528  9236 leader_election.cc:304] T 00000000000000000000000000000000 P d257d8acd2874625b68ce11143144e70 [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: d257d8acd2874625b68ce11143144e70; no voters: 
I20260812 06:19:42.131664  9236 leader_election.cc:290] T 00000000000000000000000000000000 P d257d8acd2874625b68ce11143144e70 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:42.131831  9241 raft_consensus.cc:2804] T 00000000000000000000000000000000 P d257d8acd2874625b68ce11143144e70 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:42.132036  9241 raft_consensus.cc:697] T 00000000000000000000000000000000 P d257d8acd2874625b68ce11143144e70 [term 1 LEADER]: Becoming Leader. State: Replica: d257d8acd2874625b68ce11143144e70, State: Running, Role: LEADER
I20260812 06:19:42.132148  9236 sys_catalog.cc:565] T 00000000000000000000000000000000 P d257d8acd2874625b68ce11143144e70 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:42.132185  9241 consensus_queue.cc:237] T 00000000000000000000000000000000 P d257d8acd2874625b68ce11143144e70 [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: "d257d8acd2874625b68ce11143144e70" member_type: VOTER }
I20260812 06:19:42.132664  9244 sys_catalog.cc:455] T 00000000000000000000000000000000 P d257d8acd2874625b68ce11143144e70 [sys.catalog]: SysCatalogTable state changed. Reason: New leader d257d8acd2874625b68ce11143144e70. Latest consensus state: current_term: 1 leader_uuid: "d257d8acd2874625b68ce11143144e70" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d257d8acd2874625b68ce11143144e70" member_type: VOTER } }
I20260812 06:19:42.132647  9242 sys_catalog.cc:455] T 00000000000000000000000000000000 P d257d8acd2874625b68ce11143144e70 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "d257d8acd2874625b68ce11143144e70" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d257d8acd2874625b68ce11143144e70" member_type: VOTER } }
I20260812 06:19:42.132769  9242 sys_catalog.cc:458] T 00000000000000000000000000000000 P d257d8acd2874625b68ce11143144e70 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:42.132759  9244 sys_catalog.cc:458] T 00000000000000000000000000000000 P d257d8acd2874625b68ce11143144e70 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:42.133363  9255 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:42.134065  9255 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:42.134222  8787 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:42.135967  9255 catalog_manager.cc:1383] Generated new cluster ID: cfee59dd86614f6d96be12129859c1f2
I20260812 06:19:42.136026  9255 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:42.162704  9255 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:42.163267  9255 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:42.168787  9255 catalog_manager.cc:6092] T 00000000000000000000000000000000 P d257d8acd2874625b68ce11143144e70: Generated new TSK 0
I20260812 06:19:42.168937  9255 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:42.198968  8787 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:42.200963  9279 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:42.201063  8787 server_base.cc:1061] running on GCE node
W20260812 06:19:42.201046  9275 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:42.200937  9276 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:42.201333  8787 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:42.201375  8787 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:42.201390  8787 hybrid_clock.cc:648] HybridClock initialized: now 1786515582201389 us; error 0 us; skew 500 ppm
I20260812 06:19:42.202219  8787 webserver.cc:533] Webserver started at http://127.8.148.193:42709/ using document root <none> and password file <none>
I20260812 06:19:42.202385  8787 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:42.202432  8787 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:42.202488  8787 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:42.202858  8787 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root/instance:
uuid: "bb23c6efb22f45a492662c4f980023e1"
format_stamp: "Formatted at 2026-08-12 06:19:42 on dist-test-slave-nj21"
I20260812 06:19:42.204344  8787 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:42.205175  9291 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:42.205410  8787 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:42.205476  8787 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root
uuid: "bb23c6efb22f45a492662c4f980023e1"
format_stamp: "Formatted at 2026-08-12 06:19:42 on dist-test-slave-nj21"
I20260812 06:19:42.205547  8787 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-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:42.216042  8787 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:42.216367  8787 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:42.216634  8787 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:42.217067  8787 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:42.217103  8787 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:42.217145  8787 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:42.217172  8787 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:42.221033  8787 rpc_server.cc:307] RPC server started. Bound to: 127.8.148.193:44995
I20260812 06:19:42.222572  9395 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.8.148.193:44995 every 8 connection(s)
I20260812 06:19:42.232717  9397 heartbeater.cc:344] Connected to a master server at 127.8.148.254:41287
I20260812 06:19:42.232846  9397 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:42.233073  9397 heartbeater.cc:507] Master 127.8.148.254:41287 requested a full tablet report, sending...
I20260812 06:19:42.233700  9175 ts_manager.cc:194] Registered new tserver with Master: bb23c6efb22f45a492662c4f980023e1 (127.8.148.193:44995)
I20260812 06:19:42.233937  8787 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012144954s
I20260812 06:19:42.234562  9175 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:40262
I20260812 06:19:42.240557  9175 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:40266:
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:42.249318  9332 tablet_service.cc:1511] Processing CreateTablet for tablet 1b69a16f2fd94910a276ea10ce1f1862 (DEFAULT_TABLE table=heavy-update-compaction-test [id=8ad0d4412cf7492a8acf0fb1f2fdf4d1]), partition=
I20260812 06:19:42.249593  9332 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 1b69a16f2fd94910a276ea10ce1f1862. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:42.251456  9416 tablet_bootstrap.cc:492] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Bootstrap starting.
I20260812 06:19:42.252383  9416 tablet_bootstrap.cc:654] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:42.253443  9416 tablet_bootstrap.cc:492] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: No bootstrap required, opened a new log
I20260812 06:19:42.253530  9416 ts_tablet_manager.cc:1403] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:42.254093  9416 raft_consensus.cc:359] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bb23c6efb22f45a492662c4f980023e1" member_type: VOTER last_known_addr { host: "127.8.148.193" port: 44995 } }
I20260812 06:19:42.254207  9416 raft_consensus.cc:385] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:42.254257  9416 raft_consensus.cc:740] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: bb23c6efb22f45a492662c4f980023e1, State: Initialized, Role: FOLLOWER
I20260812 06:19:42.254410  9416 consensus_queue.cc:260] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1 [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: "bb23c6efb22f45a492662c4f980023e1" member_type: VOTER last_known_addr { host: "127.8.148.193" port: 44995 } }
I20260812 06:19:42.254510  9416 raft_consensus.cc:399] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:42.254557  9416 raft_consensus.cc:493] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:42.254611  9416 raft_consensus.cc:3060] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:42.255383  9416 raft_consensus.cc:515] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bb23c6efb22f45a492662c4f980023e1" member_type: VOTER last_known_addr { host: "127.8.148.193" port: 44995 } }
I20260812 06:19:42.255523  9416 leader_election.cc:304] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1 [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: bb23c6efb22f45a492662c4f980023e1; no voters: 
I20260812 06:19:42.255775  9416 leader_election.cc:290] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:42.255872  9418 raft_consensus.cc:2804] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:42.256065  9418 raft_consensus.cc:697] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1 [term 1 LEADER]: Becoming Leader. State: Replica: bb23c6efb22f45a492662c4f980023e1, State: Running, Role: LEADER
I20260812 06:19:42.256103  9416 ts_tablet_manager.cc:1434] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:42.256153  9397 heartbeater.cc:499] Master 127.8.148.254:41287 was elected leader, sending a full tablet report...
I20260812 06:19:42.256207  9418 consensus_queue.cc:237] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1 [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: "bb23c6efb22f45a492662c4f980023e1" member_type: VOTER last_known_addr { host: "127.8.148.193" port: 44995 } }
I20260812 06:19:42.257529  9175 catalog_manager.cc:5719] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1 reported cstate change: term changed from 0 to 1, leader changed from <none> to bb23c6efb22f45a492662c4f980023e1 (127.8.148.193). New cstate: current_term: 1 leader_uuid: "bb23c6efb22f45a492662c4f980023e1" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bb23c6efb22f45a492662c4f980023e1" member_type: VOTER last_known_addr { host: "127.8.148.193" port: 44995 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:42.314410  8787 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.050s	user 0.018s	sys 0.004s
I20260812 06:19:42.472944  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushMRSOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=23.023690
I20260812 06:19:42.642916  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushMRSOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.170s	user 0.115s	sys 0.051s Metrics: {"bytes_written":12307493,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":46,"dirs.run_cpu_time_us":148,"dirs.run_wall_time_us":730,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42178,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1500}
I20260812 06:19:42.643518  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling LogGCOp(1b69a16f2fd94910a276ea10ce1f1862): free 20743880 bytes of WAL
I20260812 06:19:42.643761  9297 log_reader.cc:385] T 1b69a16f2fd94910a276ea10ce1f1862: removed 2 log segments from log reader
I20260812 06:19:42.643808  9297 log.cc:1079] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/1b69a16f2fd94910a276ea10ce1f1862/wal-000000001 (ops 1-6)
I20260812 06:19:42.643839  9297 log.cc:1079] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/1b69a16f2fd94910a276ea10ce1f1862/wal-000000002 (ops 7-11)
I20260812 06:19:42.647188  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: LogGCOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:42.647482  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling UndoDeltaBlockGCOp(1b69a16f2fd94910a276ea10ce1f1862): 20513817 bytes on disk
I20260812 06:19:42.647907  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: UndoDeltaBlockGCOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4}
I20260812 06:19:42.648267  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=2.188937
I20260812 06:19:42.658171  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3558,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.658696  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=1.000000
I20260812 06:19:42.796324  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.137s	user 0.086s	sys 0.051s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713275,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":588,"lbm_read_time_us":10105,"lbm_reads_lt_1ms":464,"lbm_write_time_us":21741,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":379,"threads_started":5,"update_count":2000}
I20260812 06:19:42.797034  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=10.126437
I20260812 06:19:42.828241  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.031s	user 0.012s	sys 0.017s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12031,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:42.828725  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=2.188937
I20260812 06:19:42.840196  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.011s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4358,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.840776  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=1.000000
I20260812 06:19:42.975894  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.135s	user 0.098s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":181,"lbm_read_time_us":7970,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23731,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14592,"update_count":2000}
I20260812 06:19:42.976404  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=10.126437
I20260812 06:19:43.018378  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.042s	user 0.024s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12986,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:43.018857  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=2.188937
I20260812 06:19:43.028764  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3598,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.029336  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=1.000000
I20260812 06:19:43.145413  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.116s	user 0.093s	sys 0.022s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":565,"lbm_read_time_us":8593,"lbm_reads_lt_1ms":472,"lbm_write_time_us":19850,"lbm_writes_lt_1ms":443,"mutex_wait_us":46,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":45824,"update_count":2000}
I20260812 06:19:43.145911  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=10.126437
I20260812 06:19:43.190045  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.044s	user 0.009s	sys 0.025s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15266,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:43.190604  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=2.188937
I20260812 06:19:43.200598  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3640,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.201236  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=1.000000
I20260812 06:19:43.326011  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.125s	user 0.098s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":687,"lbm_read_time_us":9110,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22266,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:19:43.326555  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=10.126437
I20260812 06:19:43.370955  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.044s	user 0.027s	sys 0.010s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":13966,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:43.371577  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=2.188937
I20260812 06:19:43.381933  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3826,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.382493  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=1.000000
I20260812 06:19:43.522228  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.140s	user 0.110s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":867,"lbm_read_time_us":10135,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21570,"lbm_writes_lt_1ms":443,"mutex_wait_us":280,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2000}
I20260812 06:19:43.522724  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=10.126437
I20260812 06:19:43.564215  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.041s	user 0.029s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14353,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:43.564744  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=2.188937
I20260812 06:19:43.574801  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3766,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.575354  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=1.000000
I20260812 06:19:43.693812  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.118s	user 0.086s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":731,"lbm_read_time_us":8524,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20812,"lbm_writes_lt_1ms":443,"mutex_wait_us":20,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":25344,"update_count":2000}
I20260812 06:19:43.694442  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=10.126437
I20260812 06:19:43.741796  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.047s	user 0.034s	sys 0.000s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15197,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:43.742329  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=2.188937
I20260812 06:19:43.759403  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.017s	user 0.000s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6657,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.760113  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushMRSOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=1.000000
I20260812 06:19:43.789320  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushMRSOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.029s	user 0.022s	sys 0.002s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":216,"dirs.run_wall_time_us":1257,"drs_written":1,"lbm_read_time_us":80,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1418,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:43.789983  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling LogGCOp(1b69a16f2fd94910a276ea10ce1f1862): free 112692363 bytes of WAL
I20260812 06:19:43.790177  9297 log_reader.cc:385] T 1b69a16f2fd94910a276ea10ce1f1862: removed 11 log segments from log reader
I20260812 06:19:43.790220  9297 log.cc:1079] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/1b69a16f2fd94910a276ea10ce1f1862/wal-000000003 (ops 12-16)
I20260812 06:19:43.790257  9297 log.cc:1079] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/1b69a16f2fd94910a276ea10ce1f1862/wal-000000004 (ops 17-21)
I20260812 06:19:43.790288  9297 log.cc:1079] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/1b69a16f2fd94910a276ea10ce1f1862/wal-000000005 (ops 22-26)
I20260812 06:19:43.790313  9297 log.cc:1079] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/1b69a16f2fd94910a276ea10ce1f1862/wal-000000006 (ops 27-31)
I20260812 06:19:43.790344  9297 log.cc:1079] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/1b69a16f2fd94910a276ea10ce1f1862/wal-000000007 (ops 32-36)
I20260812 06:19:43.790374  9297 log.cc:1079] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/1b69a16f2fd94910a276ea10ce1f1862/wal-000000008 (ops 37-41)
I20260812 06:19:43.790403  9297 log.cc:1079] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/1b69a16f2fd94910a276ea10ce1f1862/wal-000000009 (ops 42-46)
I20260812 06:19:43.790434  9297 log.cc:1079] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/1b69a16f2fd94910a276ea10ce1f1862/wal-000000010 (ops 47-51)
I20260812 06:19:43.790464  9297 log.cc:1079] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/1b69a16f2fd94910a276ea10ce1f1862/wal-000000011 (ops 52-56)
I20260812 06:19:43.790493  9297 log.cc:1079] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/1b69a16f2fd94910a276ea10ce1f1862/wal-000000012 (ops 57-61)
I20260812 06:19:43.790524  9297 log.cc:1079] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/1b69a16f2fd94910a276ea10ce1f1862/wal-000000013 (ops 62-66)
I20260812 06:19:43.810740  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: LogGCOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.021s	user 0.000s	sys 0.018s Metrics: {}
I20260812 06:19:43.811221  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling UndoDeltaBlockGCOp(1b69a16f2fd94910a276ea10ce1f1862): 448 bytes on disk
I20260812 06:19:43.811721  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: UndoDeltaBlockGCOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:19:43.812270  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=3.181125
I20260812 06:19:43.831202  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.019s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":6841,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:43.831630  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=2.188937
I20260812 06:19:43.840885  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.009s	user 0.007s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3252,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:43.841353  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=1.000000
I20260812 06:19:44.015872  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.174s	user 0.131s	sys 0.034s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918323,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":553,"lbm_read_time_us":11388,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33897,"lbm_writes_lt_1ms":643,"mutex_wait_us":305,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":16384,"thread_start_us":82,"threads_started":1,"update_count":3000}
I20260812 06:19:44.016734  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=14.095187
I20260812 06:19:44.065177  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.048s	user 0.030s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19036,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:44.065651  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=2.188937
I20260812 06:19:44.075706  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3638,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.076228  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=1.000000
I20260812 06:19:44.217965  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.141s	user 0.112s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":586,"lbm_read_time_us":9281,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28553,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":2500}
I20260812 06:19:44.218791  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=10.126437
I20260812 06:19:44.249955  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.031s	user 0.016s	sys 0.012s Metrics: {"bytes_written":12512611,"delete_count":0,"lbm_write_time_us":12486,"lbm_writes_lt_1ms":308,"reinsert_count":0,"update_count":1525}
I20260812 06:19:44.250445  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=2.188937
I20260812 06:19:44.261929  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3897534,"delete_count":0,"lbm_write_time_us":4247,"lbm_writes_lt_1ms":98,"reinsert_count":0,"update_count":475}
I20260812 06:19:44.262408  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=1.000000
I20260812 06:19:44.385020  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.122s	user 0.078s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":559,"lbm_read_time_us":9234,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22097,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2000}
I20260812 06:19:44.385542  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=10.126437
I20260812 06:19:44.428081  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.042s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15347,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:44.428532  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=2.188937
I20260812 06:19:44.438807  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3804,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.439484  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=1.000000
I20260812 06:19:44.557857  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.118s	user 0.091s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":671,"lbm_read_time_us":9085,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21557,"lbm_writes_lt_1ms":443,"mutex_wait_us":289,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:44.558409  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=10.126437
I20260812 06:19:44.611961  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.053s	user 0.014s	sys 0.028s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13895,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:44.612618  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=2.188937
I20260812 06:19:44.627614  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5669,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.628147  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=1.000000
I20260812 06:19:44.766364  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.138s	user 0.096s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":241,"lbm_read_time_us":10473,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20901,"lbm_writes_lt_1ms":443,"mutex_wait_us":3,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:19:44.766983  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=10.126437
I20260812 06:19:44.809902  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.043s	user 0.028s	sys 0.005s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":14809,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:44.810463  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=2.188937
I20260812 06:19:44.825635  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5559,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.826232  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=1.000000
I20260812 06:19:44.936074  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.110s	user 0.090s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":202,"lbm_read_time_us":7794,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20070,"lbm_writes_lt_1ms":443,"mutex_wait_us":33,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:19:44.936585  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=10.126437
I20260812 06:19:44.966980  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.030s	user 0.013s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":11895,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:44.967438  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=1.000000
I20260812 06:19:45.063175  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.096s	user 0.086s	sys 0.008s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16610741,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":2903,"lbm_read_time_us":5432,"lbm_reads_lt_1ms":363,"lbm_write_time_us":16917,"lbm_writes_lt_1ms":343,"mutex_wait_us":1885,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:19:45.063755  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=10.126437
I20260812 06:19:45.111873  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.048s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14175,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:45.112432  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=2.188937
I20260812 06:19:45.125979  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5307,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.126387  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushMRSOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=1.000000
I20260812 06:19:45.156558  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushMRSOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.030s	user 0.024s	sys 0.001s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":181,"dirs.run_wall_time_us":1157,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1336,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:45.157213  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling LogGCOp(1b69a16f2fd94910a276ea10ce1f1862): free 132571267 bytes of WAL
I20260812 06:19:45.157445  9297 log_reader.cc:385] T 1b69a16f2fd94910a276ea10ce1f1862: removed 13 log segments from log reader
I20260812 06:19:45.157505  9297 log.cc:1079] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/1b69a16f2fd94910a276ea10ce1f1862/wal-000000014 (ops 67-71)
I20260812 06:19:45.157550  9297 log.cc:1079] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/1b69a16f2fd94910a276ea10ce1f1862/wal-000000015 (ops 72-76)
I20260812 06:19:45.157582  9297 log.cc:1079] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/1b69a16f2fd94910a276ea10ce1f1862/wal-000000016 (ops 77-81)
I20260812 06:19:45.157603  9297 log.cc:1079] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/1b69a16f2fd94910a276ea10ce1f1862/wal-000000017 (ops 82-86)
I20260812 06:19:45.157634  9297 log.cc:1079] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/1b69a16f2fd94910a276ea10ce1f1862/wal-000000018 (ops 87-91)
I20260812 06:19:45.157666  9297 log.cc:1079] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/1b69a16f2fd94910a276ea10ce1f1862/wal-000000019 (ops 92-96)
I20260812 06:19:45.157696  9297 log.cc:1079] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/1b69a16f2fd94910a276ea10ce1f1862/wal-000000020 (ops 97-101)
I20260812 06:19:45.157720  9297 log.cc:1079] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/1b69a16f2fd94910a276ea10ce1f1862/wal-000000021 (ops 102-106)
I20260812 06:19:45.157748  9297 log.cc:1079] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/1b69a16f2fd94910a276ea10ce1f1862/wal-000000022 (ops 107-110)
I20260812 06:19:45.157774  9297 log.cc:1079] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/1b69a16f2fd94910a276ea10ce1f1862/wal-000000023 (ops 111-115)
I20260812 06:19:45.157806  9297 log.cc:1079] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/1b69a16f2fd94910a276ea10ce1f1862/wal-000000024 (ops 116-120)
I20260812 06:19:45.157835  9297 log.cc:1079] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/1b69a16f2fd94910a276ea10ce1f1862/wal-000000025 (ops 121-124)
I20260812 06:19:45.157859  9297 log.cc:1079] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/1b69a16f2fd94910a276ea10ce1f1862/wal-000000026 (ops 125-129)
I20260812 06:19:45.184953  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: LogGCOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:45.185388  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling UndoDeltaBlockGCOp(1b69a16f2fd94910a276ea10ce1f1862): 472 bytes on disk
I20260812 06:19:45.185842  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: UndoDeltaBlockGCOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4}
I20260812 06:19:45.186337  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=3.181125
I20260812 06:19:45.199888  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":4153,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:45.200309  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=2.188937
I20260812 06:19:45.209497  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3259,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:45.209928  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=1.000000
I20260812 06:19:45.384728  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.175s	user 0.131s	sys 0.040s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918320,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1085,"lbm_read_time_us":13033,"lbm_reads_lt_1ms":674,"lbm_write_time_us":28441,"lbm_writes_lt_1ms":643,"mutex_wait_us":274,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10112,"thread_start_us":89,"threads_started":1,"update_count":3000}
I20260812 06:19:45.385429  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=14.095187
I20260812 06:19:45.433633  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.048s	user 0.027s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18349,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:45.434216  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=2.188937
I20260812 06:19:45.450126  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5776,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.450678  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=1.000000
I20260812 06:19:45.624075  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.173s	user 0.134s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":277,"lbm_read_time_us":11427,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27509,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:19:45.624579  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=14.095187
I20260812 06:19:45.667048  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.042s	user 0.010s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18101,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:45.667562  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=1.000000
I20260812 06:19:45.815627  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.148s	user 0.088s	sys 0.052s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":109,"lbm_read_time_us":9912,"lbm_reads_lt_1ms":463,"lbm_write_time_us":22821,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2000}
I20260812 06:19:45.816197  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=14.095187
I20260812 06:19:45.868505  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.052s	user 0.025s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19971,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:45.869006  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=2.188937
I20260812 06:19:45.878933  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3636,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.879448  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=1.000000
I20260812 06:19:46.059441  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.180s	user 0.131s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":143,"lbm_read_time_us":10428,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27802,"lbm_writes_lt_1ms":543,"mutex_wait_us":33,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":51456,"update_count":2500}
I20260812 06:19:46.060050  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=14.095187
I20260812 06:19:46.114064  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.054s	user 0.033s	sys 0.014s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21390,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:46.114578  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=2.188937
I20260812 06:19:46.125379  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3774,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.125840  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=1.000000
I20260812 06:19:46.273769  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.148s	user 0.115s	sys 0.031s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":163,"lbm_read_time_us":10992,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27314,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":21120,"update_count":2500}
I20260812 06:19:46.274461  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=11.118625
I20260812 06:19:46.316008  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.041s	user 0.021s	sys 0.020s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":17848,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:19:46.316572  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=2.188937
I20260812 06:19:46.336288  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.020s	user 0.007s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3690,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:46.336774  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=2.188937
I20260812 06:19:46.351817  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.015s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5269,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.352468  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=1.000000
I20260812 06:19:46.494174  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.141s	user 0.120s	sys 0.020s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815793,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":583,"lbm_read_time_us":10816,"lbm_reads_lt_1ms":573,"lbm_write_time_us":25980,"lbm_writes_lt_1ms":543,"mutex_wait_us":259,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2500}
I20260812 06:19:46.494719  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=11.118625
I20260812 06:19:46.540680  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.046s	user 0.018s	sys 0.024s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17948,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:19:46.541260  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=2.188937
I20260812 06:19:46.552915  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.011s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3585,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.553396  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=2.188937
I20260812 06:19:46.566184  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4622,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:46.566717  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushMRSOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=1.000000
I20260812 06:19:46.601153  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushMRSOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.034s	user 0.029s	sys 0.004s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":169,"dirs.run_wall_time_us":1240,"drs_written":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2301,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31,"spinlock_wait_cycles":1280}
I20260812 06:19:46.601923  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling LogGCOp(1b69a16f2fd94910a276ea10ce1f1862): free 124710562 bytes of WAL
I20260812 06:19:46.602203  9297 log_reader.cc:385] T 1b69a16f2fd94910a276ea10ce1f1862: removed 12 log segments from log reader
I20260812 06:19:46.602263  9297 log.cc:1079] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/1b69a16f2fd94910a276ea10ce1f1862/wal-000000027 (ops 130-134)
I20260812 06:19:46.602299  9297 log.cc:1079] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/1b69a16f2fd94910a276ea10ce1f1862/wal-000000028 (ops 135-139)
I20260812 06:19:46.602339  9297 log.cc:1079] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/1b69a16f2fd94910a276ea10ce1f1862/wal-000000029 (ops 140-144)
I20260812 06:19:46.602368  9297 log.cc:1079] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/1b69a16f2fd94910a276ea10ce1f1862/wal-000000030 (ops 145-149)
I20260812 06:19:46.602406  9297 log.cc:1079] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/1b69a16f2fd94910a276ea10ce1f1862/wal-000000031 (ops 150-154)
I20260812 06:19:46.602443  9297 log.cc:1079] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/1b69a16f2fd94910a276ea10ce1f1862/wal-000000032 (ops 155-159)
I20260812 06:19:46.602481  9297 log.cc:1079] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/1b69a16f2fd94910a276ea10ce1f1862/wal-000000033 (ops 160-164)
I20260812 06:19:46.602519  9297 log.cc:1079] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/1b69a16f2fd94910a276ea10ce1f1862/wal-000000034 (ops 165-169)
I20260812 06:19:46.602556  9297 log.cc:1079] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/1b69a16f2fd94910a276ea10ce1f1862/wal-000000035 (ops 170-174)
I20260812 06:19:46.602594  9297 log.cc:1079] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/1b69a16f2fd94910a276ea10ce1f1862/wal-000000036 (ops 175-179)
I20260812 06:19:46.602631  9297 log.cc:1079] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/1b69a16f2fd94910a276ea10ce1f1862/wal-000000037 (ops 180-184)
I20260812 06:19:46.602670  9297 log.cc:1079] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: Deleting log segment in path: /tmp/dist-test-taskfu_9fr/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515576986942-8787-0/minicluster-data/ts-0-root/wals/1b69a16f2fd94910a276ea10ce1f1862/wal-000000038 (ops 185-189)
I20260812 06:19:46.623024  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: LogGCOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.021s	user 0.000s	sys 0.018s Metrics: {}
I20260812 06:19:46.623446  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=2.188937
I20260812 06:19:46.644796  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.021s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":7127,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.645282  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=2.188937
I20260812 06:19:46.662979  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.018s	user 0.008s	sys 0.006s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3692,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.663650  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=1.000000
I20260812 06:19:46.862370  8787 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.548s	user 1.671s	sys 0.174s
I20260812 06:19:46.871790  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.208s	user 0.145s	sys 0.061s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020854,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"lbm_read_time_us":14402,"lbm_reads_lt_1ms":771,"lbm_write_time_us":36139,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":3500}
I20260812 06:19:46.872247  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=14.095187
I20260812 06:19:46.902837  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: FlushDeltaMemStoresOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.030s	user 0.021s	sys 0.008s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":13895,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:46.903287  9398 maintenance_manager.cc:419] P bb23c6efb22f45a492662c4f980023e1: Scheduling MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862): perf score=1.000000
I20260812 06:19:46.943459  8787 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.081s	user 0.001s	sys 0.000s
I20260812 06:19:46.944068  8787 tablet_server.cc:179] TabletServer@127.8.148.193:0 shutting down...
I20260812 06:19:47.035437  9297 maintenance_manager.cc:643] P bb23c6efb22f45a492662c4f980023e1: MajorDeltaCompactionOp(1b69a16f2fd94910a276ea10ce1f1862) complete. Timing: real 0.132s	user 0.090s	sys 0.039s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713154,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":603,"lbm_read_time_us":6832,"lbm_reads_lt_1ms":467,"lbm_write_time_us":23728,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":113,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2000}
I20260812 06:19:47.036088  8787 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:47.036317  8787 tablet_replica.cc:333] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1: stopping tablet replica
I20260812 06:19:47.036479  8787 raft_consensus.cc:2243] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:47.036641  8787 raft_consensus.cc:2272] T 1b69a16f2fd94910a276ea10ce1f1862 P bb23c6efb22f45a492662c4f980023e1 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:47.051200  8787 tablet_server.cc:196] TabletServer@127.8.148.193:0 shutdown complete.
I20260812 06:19:47.074549  8787 master.cc:562] Master@127.8.148.254:41287 shutting down...
I20260812 06:19:47.077714  8787 raft_consensus.cc:2243] T 00000000000000000000000000000000 P d257d8acd2874625b68ce11143144e70 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:47.077912  8787 raft_consensus.cc:2272] T 00000000000000000000000000000000 P d257d8acd2874625b68ce11143144e70 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:47.077987  8787 tablet_replica.cc:333] T 00000000000000000000000000000000 P d257d8acd2874625b68ce11143144e70: stopping tablet replica
I20260812 06:19:47.090168  8787 master.cc:584] Master@127.8.148.254:41287 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5078 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10165 ms total)

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