[==========] 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:27.827883 24159 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.23.151.254:39195
I20260812 06:19:27.828935 24159 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:27.829574 24159 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:27.836257 24170 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:27.836453 24159 server_base.cc:1061] running on GCE node
W20260812 06:19:27.836261 24165 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:27.836728 24166 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:27.837289 24159 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:27.837531 24159 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:27.837606 24159 hybrid_clock.cc:648] HybridClock initialized: now 1786515567837603 us; error 0 us; skew 500 ppm
I20260812 06:19:27.839728 24159 webserver.cc:533] Webserver started at http://127.23.151.254:39387/ using document root <none> and password file <none>
I20260812 06:19:27.840364 24159 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:27.840451 24159 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:27.840695 24159 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:27.842483 24159 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/master-0-root/instance:
uuid: "0b838f082fb44cbdb23394b2d5b45096"
format_stamp: "Formatted at 2026-08-12 06:19:27 on dist-test-slave-c12x"
I20260812 06:19:27.846844 24159 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.002s	sys 0.004s
I20260812 06:19:27.849242 24175 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:27.850553 24159 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.000s	sys 0.001s
I20260812 06:19:27.850703 24159 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/master-0-root
uuid: "0b838f082fb44cbdb23394b2d5b45096"
format_stamp: "Formatted at 2026-08-12 06:19:27 on dist-test-slave-c12x"
I20260812 06:19:27.850831 24159 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-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:27.861236 24159 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:27.861886 24159 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:27.862082 24159 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:27.870446 24159 rpc_server.cc:307] RPC server started. Bound to: 127.23.151.254:39195
I20260812 06:19:27.870455 24260 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.151.254:39195 every 8 connection(s)
I20260812 06:19:27.872777 24261 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:27.878147 24261 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0b838f082fb44cbdb23394b2d5b45096: Bootstrap starting.
I20260812 06:19:27.880465 24261 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 0b838f082fb44cbdb23394b2d5b45096: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:27.881335 24261 log.cc:826] T 00000000000000000000000000000000 P 0b838f082fb44cbdb23394b2d5b45096: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:27.883091 24261 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0b838f082fb44cbdb23394b2d5b45096: No bootstrap required, opened a new log
I20260812 06:19:27.885985 24261 raft_consensus.cc:359] T 00000000000000000000000000000000 P 0b838f082fb44cbdb23394b2d5b45096 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0b838f082fb44cbdb23394b2d5b45096" member_type: VOTER }
I20260812 06:19:27.886152 24261 raft_consensus.cc:385] T 00000000000000000000000000000000 P 0b838f082fb44cbdb23394b2d5b45096 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:27.886193 24261 raft_consensus.cc:740] T 00000000000000000000000000000000 P 0b838f082fb44cbdb23394b2d5b45096 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0b838f082fb44cbdb23394b2d5b45096, State: Initialized, Role: FOLLOWER
I20260812 06:19:27.886716 24261 consensus_queue.cc:260] T 00000000000000000000000000000000 P 0b838f082fb44cbdb23394b2d5b45096 [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: "0b838f082fb44cbdb23394b2d5b45096" member_type: VOTER }
I20260812 06:19:27.886847 24261 raft_consensus.cc:399] T 00000000000000000000000000000000 P 0b838f082fb44cbdb23394b2d5b45096 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:27.886893 24261 raft_consensus.cc:493] T 00000000000000000000000000000000 P 0b838f082fb44cbdb23394b2d5b45096 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:27.886976 24261 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 0b838f082fb44cbdb23394b2d5b45096 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:27.887846 24261 raft_consensus.cc:515] T 00000000000000000000000000000000 P 0b838f082fb44cbdb23394b2d5b45096 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0b838f082fb44cbdb23394b2d5b45096" member_type: VOTER }
I20260812 06:19:27.888252 24261 leader_election.cc:304] T 00000000000000000000000000000000 P 0b838f082fb44cbdb23394b2d5b45096 [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: 0b838f082fb44cbdb23394b2d5b45096; no voters: 
I20260812 06:19:27.888545 24261 leader_election.cc:290] T 00000000000000000000000000000000 P 0b838f082fb44cbdb23394b2d5b45096 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:27.888760 24265 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 0b838f082fb44cbdb23394b2d5b45096 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:27.889108 24265 raft_consensus.cc:697] T 00000000000000000000000000000000 P 0b838f082fb44cbdb23394b2d5b45096 [term 1 LEADER]: Becoming Leader. State: Replica: 0b838f082fb44cbdb23394b2d5b45096, State: Running, Role: LEADER
I20260812 06:19:27.889667 24261 sys_catalog.cc:565] T 00000000000000000000000000000000 P 0b838f082fb44cbdb23394b2d5b45096 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:27.889698 24265 consensus_queue.cc:237] T 00000000000000000000000000000000 P 0b838f082fb44cbdb23394b2d5b45096 [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: "0b838f082fb44cbdb23394b2d5b45096" member_type: VOTER }
I20260812 06:19:27.891922 24267 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0b838f082fb44cbdb23394b2d5b45096 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "0b838f082fb44cbdb23394b2d5b45096" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0b838f082fb44cbdb23394b2d5b45096" member_type: VOTER } }
I20260812 06:19:27.891947 24268 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0b838f082fb44cbdb23394b2d5b45096 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 0b838f082fb44cbdb23394b2d5b45096. Latest consensus state: current_term: 1 leader_uuid: "0b838f082fb44cbdb23394b2d5b45096" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0b838f082fb44cbdb23394b2d5b45096" member_type: VOTER } }
I20260812 06:19:27.892096 24159 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:27.892072 24268 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0b838f082fb44cbdb23394b2d5b45096 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:27.892071 24267 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0b838f082fb44cbdb23394b2d5b45096 [sys.catalog]: This master's current role is: LEADER
W20260812 06:19:27.894129 24286 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 0b838f082fb44cbdb23394b2d5b45096: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:19:27.894191 24286 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:19:27.894275 24287 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:27.894985 24287 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:27.900444 24287 catalog_manager.cc:1383] Generated new cluster ID: bb23f1dd945f44c3845ba7809f880c38
I20260812 06:19:27.900522 24287 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:27.917958 24287 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:27.919260 24287 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:27.927304 24287 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 0b838f082fb44cbdb23394b2d5b45096: Generated new TSK 0
I20260812 06:19:27.928084 24287 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:27.956969 24159 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:27.959867 24293 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:27.959930 24294 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:27.960086 24298 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:27.960281 24159 server_base.cc:1061] running on GCE node
I20260812 06:19:27.960500 24159 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:27.960557 24159 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:27.960580 24159 hybrid_clock.cc:648] HybridClock initialized: now 1786515567960580 us; error 0 us; skew 500 ppm
I20260812 06:19:27.961710 24159 webserver.cc:533] Webserver started at http://127.23.151.193:36491/ using document root <none> and password file <none>
I20260812 06:19:27.961892 24159 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:27.961961 24159 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:27.962041 24159 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:27.962800 24159 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root/instance:
uuid: "fb1906bd6e29475eb1bef3b14c02c754"
format_stamp: "Formatted at 2026-08-12 06:19:27 on dist-test-slave-c12x"
I20260812 06:19:27.965063 24159 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:19:27.966431 24307 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:27.966825 24159 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:27.966915 24159 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root
uuid: "fb1906bd6e29475eb1bef3b14c02c754"
format_stamp: "Formatted at 2026-08-12 06:19:27 on dist-test-slave-c12x"
I20260812 06:19:27.967031 24159 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-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:27.977941 24159 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:27.978456 24159 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:27.979007 24159 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:27.979946 24159 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:27.980020 24159 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:27.980088 24159 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:27.980134 24159 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:27.987076 24159 rpc_server.cc:307] RPC server started. Bound to: 127.23.151.193:34119
I20260812 06:19:27.987104 24406 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.151.193:34119 every 8 connection(s)
I20260812 06:19:28.002313 24408 heartbeater.cc:344] Connected to a master server at 127.23.151.254:39195
I20260812 06:19:28.002645 24408 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:28.003234 24408 heartbeater.cc:507] Master 127.23.151.254:39195 requested a full tablet report, sending...
I20260812 06:19:28.004871 24205 ts_manager.cc:194] Registered new tserver with Master: fb1906bd6e29475eb1bef3b14c02c754 (127.23.151.193:34119)
I20260812 06:19:28.005179 24159 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01716776s
I20260812 06:19:28.006331 24205 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:39458
I20260812 06:19:28.015686 24205 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:39464:
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:28.030084 24353 tablet_service.cc:1511] Processing CreateTablet for tablet 0d1051b15a6f4ab4bfd6eb776482811b (DEFAULT_TABLE table=heavy-update-compaction-test [id=07030616f9634b42ad2f8b30a22f9998]), partition=
I20260812 06:19:28.030565 24353 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 0d1051b15a6f4ab4bfd6eb776482811b. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:28.033607 24427 tablet_bootstrap.cc:492] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Bootstrap starting.
I20260812 06:19:28.034608 24427 tablet_bootstrap.cc:654] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:28.035866 24427 tablet_bootstrap.cc:492] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: No bootstrap required, opened a new log
I20260812 06:19:28.036019 24427 ts_tablet_manager.cc:1403] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:28.036499 24427 raft_consensus.cc:359] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fb1906bd6e29475eb1bef3b14c02c754" member_type: VOTER last_known_addr { host: "127.23.151.193" port: 34119 } }
I20260812 06:19:28.036654 24427 raft_consensus.cc:385] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:28.036751 24427 raft_consensus.cc:740] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: fb1906bd6e29475eb1bef3b14c02c754, State: Initialized, Role: FOLLOWER
I20260812 06:19:28.036986 24427 consensus_queue.cc:260] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754 [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: "fb1906bd6e29475eb1bef3b14c02c754" member_type: VOTER last_known_addr { host: "127.23.151.193" port: 34119 } }
I20260812 06:19:28.037106 24427 raft_consensus.cc:399] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:28.037160 24427 raft_consensus.cc:493] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:28.037225 24427 raft_consensus.cc:3060] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:28.038018 24427 raft_consensus.cc:515] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fb1906bd6e29475eb1bef3b14c02c754" member_type: VOTER last_known_addr { host: "127.23.151.193" port: 34119 } }
I20260812 06:19:28.038180 24427 leader_election.cc:304] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754 [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: fb1906bd6e29475eb1bef3b14c02c754; no voters: 
I20260812 06:19:28.038426 24427 leader_election.cc:290] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:28.038528 24431 raft_consensus.cc:2804] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:28.038774 24427 ts_tablet_manager.cc:1434] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:28.039252 24408 heartbeater.cc:499] Master 127.23.151.254:39195 was elected leader, sending a full tablet report...
I20260812 06:19:28.039649 24431 raft_consensus.cc:697] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754 [term 1 LEADER]: Becoming Leader. State: Replica: fb1906bd6e29475eb1bef3b14c02c754, State: Running, Role: LEADER
I20260812 06:19:28.039835 24431 consensus_queue.cc:237] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754 [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: "fb1906bd6e29475eb1bef3b14c02c754" member_type: VOTER last_known_addr { host: "127.23.151.193" port: 34119 } }
I20260812 06:19:28.042615 24203 catalog_manager.cc:5719] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754 reported cstate change: term changed from 0 to 1, leader changed from <none> to fb1906bd6e29475eb1bef3b14c02c754 (127.23.151.193). New cstate: current_term: 1 leader_uuid: "fb1906bd6e29475eb1bef3b14c02c754" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fb1906bd6e29475eb1bef3b14c02c754" member_type: VOTER last_known_addr { host: "127.23.151.193" port: 34119 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:28.110071 24159 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.060s	user 0.018s	sys 0.012s
I20260812 06:19:28.238579 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushMRSOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=15.086190
I20260812 06:19:28.405521 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushMRSOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.167s	user 0.130s	sys 0.031s Metrics: {"bytes_written":12307491,"cfile_init":1,"compiler_manager_pool.queue_time_us":1769,"delete_count":0,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":231,"dirs.run_wall_time_us":822,"drs_written":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40834,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"thread_start_us":1675,"threads_started":1,"update_count":1500}
I20260812 06:19:28.407227 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling LogGCOp(0d1051b15a6f4ab4bfd6eb776482811b): free 11976772 bytes of WAL
I20260812 06:19:28.407589 24315 log_reader.cc:385] T 0d1051b15a6f4ab4bfd6eb776482811b: removed 1 log segments from log reader
I20260812 06:19:28.407661 24315 log.cc:1079] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d1051b15a6f4ab4bfd6eb776482811b/wal-000000001 (ops 1-6)
I20260812 06:19:28.410876 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: LogGCOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:28.411314 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling UndoDeltaBlockGCOp(0d1051b15a6f4ab4bfd6eb776482811b): 12308957 bytes on disk
I20260812 06:19:28.412030 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: UndoDeltaBlockGCOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4}
I20260812 06:19:28.412514 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=2.188937
I20260812 06:19:28.430377 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.018s	user 0.000s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5196,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:28.430817 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=2.188937
I20260812 06:19:28.445741 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5492,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:28.446657 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling MajorDeltaCompactionOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=1.000000
I20260812 06:19:28.617657 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: MajorDeltaCompactionOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.171s	user 0.128s	sys 0.040s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733844,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":859,"lbm_read_time_us":10917,"lbm_reads_lt_1ms":569,"lbm_write_time_us":31320,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"thread_start_us":364,"threads_started":5,"update_count":2500}
I20260812 06:19:28.618263 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=10.126437
I20260812 06:19:28.653226 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.035s	user 0.022s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14152,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:28.653862 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=2.188937
I20260812 06:19:28.668395 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.014s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5148,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:28.669027 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling MajorDeltaCompactionOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=1.000000
I20260812 06:19:28.785099 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: MajorDeltaCompactionOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.116s	user 0.087s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":618,"lbm_read_time_us":7936,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22401,"lbm_writes_lt_1ms":443,"mutex_wait_us":110,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":2000}
I20260812 06:19:28.785670 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=10.126437
I20260812 06:19:28.822402 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.037s	user 0.029s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15044,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:28.822911 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=2.188937
I20260812 06:19:28.837083 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5628,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:28.837725 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling MajorDeltaCompactionOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=1.000000
I20260812 06:19:28.961829 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: MajorDeltaCompactionOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.124s	user 0.098s	sys 0.026s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":458,"lbm_read_time_us":9080,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22934,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:28.962466 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=10.126437
I20260812 06:19:29.009763 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.047s	user 0.023s	sys 0.022s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16188,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:29.010385 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=2.188937
I20260812 06:19:29.020856 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4110,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:29.021273 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling MajorDeltaCompactionOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=1.000000
I20260812 06:19:29.161032 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: MajorDeltaCompactionOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.140s	user 0.096s	sys 0.043s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":817,"lbm_read_time_us":9974,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22332,"lbm_writes_lt_1ms":443,"mutex_wait_us":307,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:19:29.161610 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=10.126437
I20260812 06:19:29.205559 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.044s	user 0.023s	sys 0.009s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14925,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:29.205987 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=2.188937
I20260812 06:19:29.216693 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4155,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:29.217308 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling MajorDeltaCompactionOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=1.000000
I20260812 06:19:29.341859 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: MajorDeltaCompactionOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.124s	user 0.094s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":909,"dirs.run_cpu_time_us":603,"dirs.run_wall_time_us":2514,"lbm_read_time_us":8728,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24028,"lbm_writes_lt_1ms":443,"mutex_wait_us":217,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9856,"update_count":2000}
I20260812 06:19:29.342485 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=10.126437
I20260812 06:19:29.384176 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.041s	user 0.011s	sys 0.024s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15889,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:29.384656 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=2.188937
I20260812 06:19:29.395954 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4371,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:29.396482 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling MajorDeltaCompactionOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=1.000000
I20260812 06:19:29.525099 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: MajorDeltaCompactionOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.128s	user 0.100s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":233,"lbm_read_time_us":8959,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26397,"lbm_writes_lt_1ms":443,"mutex_wait_us":29,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":2000}
I20260812 06:19:29.525892 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=10.126437
I20260812 06:19:29.570044 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.044s	user 0.019s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15977,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:29.570580 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=2.188937
I20260812 06:19:29.582434 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4449,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:29.583063 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushMRSOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=1.000000
I20260812 06:19:29.613937 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushMRSOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.031s	user 0.026s	sys 0.003s Metrics: {"bytes_written":1193504,"cfile_init":1,"dirs.queue_time_us":99,"dirs.run_cpu_time_us":257,"dirs.run_wall_time_us":1095,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2013,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:29.614881 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling LogGCOp(0d1051b15a6f4ab4bfd6eb776482811b): free 125163517 bytes of WAL
I20260812 06:19:29.615165 24315 log_reader.cc:385] T 0d1051b15a6f4ab4bfd6eb776482811b: removed 13 log segments from log reader
I20260812 06:19:29.615223 24315 log.cc:1079] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d1051b15a6f4ab4bfd6eb776482811b/wal-000000002 (ops 7-11)
I20260812 06:19:29.615279 24315 log.cc:1079] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d1051b15a6f4ab4bfd6eb776482811b/wal-000000003 (ops 12-16)
I20260812 06:19:29.615327 24315 log.cc:1079] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d1051b15a6f4ab4bfd6eb776482811b/wal-000000004 (ops 17-20)
I20260812 06:19:29.615372 24315 log.cc:1079] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d1051b15a6f4ab4bfd6eb776482811b/wal-000000005 (ops 21-25)
I20260812 06:19:29.615413 24315 log.cc:1079] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d1051b15a6f4ab4bfd6eb776482811b/wal-000000006 (ops 26-30)
I20260812 06:19:29.615476 24315 log.cc:1079] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d1051b15a6f4ab4bfd6eb776482811b/wal-000000007 (ops 31-34)
I20260812 06:19:29.615523 24315 log.cc:1079] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d1051b15a6f4ab4bfd6eb776482811b/wal-000000008 (ops 35-39)
I20260812 06:19:29.615578 24315 log.cc:1079] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d1051b15a6f4ab4bfd6eb776482811b/wal-000000009 (ops 40-44)
I20260812 06:19:29.615618 24315 log.cc:1079] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d1051b15a6f4ab4bfd6eb776482811b/wal-000000010 (ops 45-48)
I20260812 06:19:29.615658 24315 log.cc:1079] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d1051b15a6f4ab4bfd6eb776482811b/wal-000000011 (ops 49-53)
I20260812 06:19:29.615706 24315 log.cc:1079] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d1051b15a6f4ab4bfd6eb776482811b/wal-000000012 (ops 54-58)
I20260812 06:19:29.615746 24315 log.cc:1079] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d1051b15a6f4ab4bfd6eb776482811b/wal-000000013 (ops 59-62)
I20260812 06:19:29.615779 24315 log.cc:1079] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d1051b15a6f4ab4bfd6eb776482811b/wal-000000014 (ops 63-67)
I20260812 06:19:29.647629 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: LogGCOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.033s	user 0.002s	sys 0.031s Metrics: {}
I20260812 06:19:29.648283 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling UndoDeltaBlockGCOp(0d1051b15a6f4ab4bfd6eb776482811b): 462 bytes on disk
I20260812 06:19:29.648993 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: UndoDeltaBlockGCOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4}
I20260812 06:19:29.649531 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=3.181125
I20260812 06:19:29.669587 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.020s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":6926,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:29.670032 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=2.188937
I20260812 06:19:29.680346 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.010s	user 0.003s	sys 0.006s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3831,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:29.680863 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling MajorDeltaCompactionOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=1.000000
I20260812 06:19:29.858991 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: MajorDeltaCompactionOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.178s	user 0.111s	sys 0.056s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836361,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2555,"lbm_read_time_us":13571,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34364,"lbm_writes_lt_1ms":643,"mutex_wait_us":49,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5760,"thread_start_us":78,"threads_started":1,"update_count":3000}
I20260812 06:19:29.859630 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=14.095187
I20260812 06:19:29.915794 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.056s	user 0.023s	sys 0.033s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":27202,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:29.916349 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=2.188937
I20260812 06:19:29.934875 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.018s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4972,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:29.935518 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling MajorDeltaCompactionOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=1.000000
I20260812 06:19:30.082980 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: MajorDeltaCompactionOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.147s	user 0.110s	sys 0.033s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":692,"lbm_read_time_us":8524,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28697,"lbm_writes_lt_1ms":543,"mutex_wait_us":278,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:19:30.083590 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=14.095187
I20260812 06:19:30.133746 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.050s	user 0.032s	sys 0.013s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20776,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:30.134246 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=2.188937
I20260812 06:19:30.145907 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4177,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:30.146512 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling MajorDeltaCompactionOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=1.000000
I20260812 06:19:30.328624 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: MajorDeltaCompactionOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.182s	user 0.124s	sys 0.054s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":223,"lbm_read_time_us":11689,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30960,"lbm_writes_lt_1ms":543,"mutex_wait_us":34,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":85120,"update_count":2500}
I20260812 06:19:30.329519 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=14.095187
I20260812 06:19:30.390713 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.061s	user 0.023s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21028,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:30.391214 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=2.188937
I20260812 06:19:30.402479 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4302,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:30.403115 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling MajorDeltaCompactionOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=1.000000
I20260812 06:19:30.584033 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: MajorDeltaCompactionOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.181s	user 0.126s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1591,"lbm_read_time_us":12232,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31140,"lbm_writes_lt_1ms":543,"mutex_wait_us":456,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10368,"update_count":2500}
I20260812 06:19:30.584532 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=14.095187
I20260812 06:19:30.641322 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.057s	user 0.027s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19606,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:30.641806 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=2.188937
I20260812 06:19:30.654191 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4277,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:30.654923 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling MajorDeltaCompactionOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=1.000000
I20260812 06:19:30.838693 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: MajorDeltaCompactionOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.184s	user 0.120s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1002,"lbm_read_time_us":12040,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30870,"lbm_writes_lt_1ms":543,"mutex_wait_us":69,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:30.839299 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=14.095187
I20260812 06:19:30.901088 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.062s	user 0.035s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21494,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:30.901625 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=2.188937
I20260812 06:19:30.912627 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4265,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:30.913120 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling MajorDeltaCompactionOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=1.000000
I20260812 06:19:31.085635 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: MajorDeltaCompactionOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.172s	user 0.125s	sys 0.047s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":153,"lbm_read_time_us":13054,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29340,"lbm_writes_lt_1ms":543,"mutex_wait_us":31,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":2500}
I20260812 06:19:31.086337 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=11.118625
I20260812 06:19:31.117115 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.031s	user 0.025s	sys 0.004s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13410,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:31.117753 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=2.188937
I20260812 06:19:31.132417 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5598,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:31.132999 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushMRSOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=1.000000
I20260812 06:19:31.168040 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushMRSOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.035s	user 0.031s	sys 0.004s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":209,"dirs.run_wall_time_us":1294,"drs_written":1,"lbm_read_time_us":99,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2492,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:31.168988 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling LogGCOp(0d1051b15a6f4ab4bfd6eb776482811b): free 121006488 bytes of WAL
I20260812 06:19:31.169298 24315 log_reader.cc:385] T 0d1051b15a6f4ab4bfd6eb776482811b: removed 12 log segments from log reader
I20260812 06:19:31.169381 24315 log.cc:1079] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d1051b15a6f4ab4bfd6eb776482811b/wal-000000015 (ops 68-72)
I20260812 06:19:31.169440 24315 log.cc:1079] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d1051b15a6f4ab4bfd6eb776482811b/wal-000000016 (ops 73-77)
I20260812 06:19:31.169489 24315 log.cc:1079] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d1051b15a6f4ab4bfd6eb776482811b/wal-000000017 (ops 78-82)
I20260812 06:19:31.169539 24315 log.cc:1079] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d1051b15a6f4ab4bfd6eb776482811b/wal-000000018 (ops 83-87)
I20260812 06:19:31.169587 24315 log.cc:1079] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d1051b15a6f4ab4bfd6eb776482811b/wal-000000019 (ops 88-92)
I20260812 06:19:31.169634 24315 log.cc:1079] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d1051b15a6f4ab4bfd6eb776482811b/wal-000000020 (ops 93-97)
I20260812 06:19:31.169691 24315 log.cc:1079] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d1051b15a6f4ab4bfd6eb776482811b/wal-000000021 (ops 98-102)
I20260812 06:19:31.169741 24315 log.cc:1079] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d1051b15a6f4ab4bfd6eb776482811b/wal-000000022 (ops 103-107)
I20260812 06:19:31.169795 24315 log.cc:1079] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d1051b15a6f4ab4bfd6eb776482811b/wal-000000023 (ops 108-112)
I20260812 06:19:31.169842 24315 log.cc:1079] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d1051b15a6f4ab4bfd6eb776482811b/wal-000000024 (ops 113-116)
I20260812 06:19:31.169889 24315 log.cc:1079] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d1051b15a6f4ab4bfd6eb776482811b/wal-000000025 (ops 117-121)
I20260812 06:19:31.169937 24315 log.cc:1079] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d1051b15a6f4ab4bfd6eb776482811b/wal-000000026 (ops 122-126)
I20260812 06:19:31.195890 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: LogGCOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:31.196324 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=3.181125
I20260812 06:19:31.222433 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.026s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4607,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:31.222879 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=2.188937
I20260812 06:19:31.232332 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.009s	user 0.008s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3490,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:31.232765 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling UndoDeltaBlockGCOp(0d1051b15a6f4ab4bfd6eb776482811b): 482 bytes on disk
I20260812 06:19:31.233171 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: UndoDeltaBlockGCOp(0d1051b15a6f4ab4bfd6eb776482811b) 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:31.233664 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling MajorDeltaCompactionOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=1.000000
I20260812 06:19:31.427663 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: MajorDeltaCompactionOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.194s	user 0.118s	sys 0.072s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836352,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":11671,"lbm_read_time_us":12657,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34501,"lbm_writes_lt_1ms":643,"mutex_wait_us":3869,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":81,"threads_started":1,"update_count":3000}
I20260812 06:19:31.428329 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=14.095187
I20260812 06:19:31.479172 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.050s	user 0.029s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22442,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:31.479763 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=2.188937
I20260812 06:19:31.497144 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.017s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6913,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:31.497721 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling MajorDeltaCompactionOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=1.000000
I20260812 06:19:31.670166 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: MajorDeltaCompactionOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.172s	user 0.104s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":729,"lbm_read_time_us":11918,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27259,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8320,"update_count":2500}
I20260812 06:19:31.670642 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=14.095187
I20260812 06:19:31.741138 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.070s	user 0.030s	sys 0.039s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25267,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:31.741776 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=2.188937
I20260812 06:19:31.754145 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4257,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:31.754727 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling MajorDeltaCompactionOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=1.000000
I20260812 06:19:31.941164 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: MajorDeltaCompactionOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.186s	user 0.110s	sys 0.072s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":220,"lbm_read_time_us":13494,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31960,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:19:31.941648 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=14.095187
I20260812 06:19:31.991741 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.050s	user 0.024s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20468,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:31.992363 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=2.188937
I20260812 06:19:32.018437 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.026s	user 0.008s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6086,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:32.019232 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling MajorDeltaCompactionOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=1.000000
I20260812 06:19:32.205489 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: MajorDeltaCompactionOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.186s	user 0.125s	sys 0.061s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":349,"lbm_read_time_us":14996,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30189,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2500}
I20260812 06:19:32.206377 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=11.118625
I20260812 06:19:32.250707 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.044s	user 0.021s	sys 0.020s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":19396,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:19:32.251214 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=2.188937
I20260812 06:19:32.275643 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.024s	user 0.012s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6250,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:32.276163 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=2.188937
I20260812 06:19:32.285449 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3390,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:32.286008 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling MajorDeltaCompactionOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=1.000000
I20260812 06:19:32.458972 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: MajorDeltaCompactionOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.173s	user 0.120s	sys 0.044s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733836,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":187,"lbm_read_time_us":9837,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28988,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14976,"update_count":2500}
I20260812 06:19:32.459944 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=11.118625
I20260812 06:19:32.495977 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.036s	user 0.026s	sys 0.009s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":15362,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:32.496677 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=2.188937
I20260812 06:19:32.511761 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5486,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:32.512279 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling MajorDeltaCompactionOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=1.000000
I20260812 06:19:32.640874 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: MajorDeltaCompactionOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.128s	user 0.100s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631302,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":991,"lbm_read_time_us":8855,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27341,"lbm_writes_lt_1ms":443,"mutex_wait_us":327,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":384,"update_count":2000}
I20260812 06:19:32.642441 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=10.126437
I20260812 06:19:32.678079 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.035s	user 0.017s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15582,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:19:32.678619 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=2.188937
I20260812 06:19:32.694322 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.016s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5250,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:32.694777 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushMRSOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=1.000000
I20260812 06:19:32.724189 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushMRSOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.029s	user 0.025s	sys 0.004s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":253,"dirs.run_wall_time_us":1208,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2121,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:32.724886 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling LogGCOp(0d1051b15a6f4ab4bfd6eb776482811b): free 124710554 bytes of WAL
I20260812 06:19:32.725138 24315 log_reader.cc:385] T 0d1051b15a6f4ab4bfd6eb776482811b: removed 12 log segments from log reader
I20260812 06:19:32.725209 24315 log.cc:1079] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d1051b15a6f4ab4bfd6eb776482811b/wal-000000027 (ops 127-131)
I20260812 06:19:32.725263 24315 log.cc:1079] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d1051b15a6f4ab4bfd6eb776482811b/wal-000000028 (ops 132-136)
I20260812 06:19:32.725323 24315 log.cc:1079] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d1051b15a6f4ab4bfd6eb776482811b/wal-000000029 (ops 137-141)
I20260812 06:19:32.725364 24315 log.cc:1079] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d1051b15a6f4ab4bfd6eb776482811b/wal-000000030 (ops 142-146)
I20260812 06:19:32.725400 24315 log.cc:1079] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d1051b15a6f4ab4bfd6eb776482811b/wal-000000031 (ops 147-151)
I20260812 06:19:32.725436 24315 log.cc:1079] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d1051b15a6f4ab4bfd6eb776482811b/wal-000000032 (ops 152-156)
I20260812 06:19:32.725473 24315 log.cc:1079] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d1051b15a6f4ab4bfd6eb776482811b/wal-000000033 (ops 157-161)
I20260812 06:19:32.725510 24315 log.cc:1079] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d1051b15a6f4ab4bfd6eb776482811b/wal-000000034 (ops 162-166)
I20260812 06:19:32.725544 24315 log.cc:1079] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d1051b15a6f4ab4bfd6eb776482811b/wal-000000035 (ops 167-171)
I20260812 06:19:32.725584 24315 log.cc:1079] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d1051b15a6f4ab4bfd6eb776482811b/wal-000000036 (ops 172-176)
I20260812 06:19:32.725617 24315 log.cc:1079] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d1051b15a6f4ab4bfd6eb776482811b/wal-000000037 (ops 177-181)
I20260812 06:19:32.725654 24315 log.cc:1079] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d1051b15a6f4ab4bfd6eb776482811b/wal-000000038 (ops 182-186)
I20260812 06:19:32.755291 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: LogGCOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.030s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:32.755816 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=4.173312
I20260812 06:19:32.774825 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.019s	user 0.008s	sys 0.009s Metrics: {"bytes_written":6276942,"delete_count":0,"lbm_write_time_us":7679,"lbm_writes_lt_1ms":156,"reinsert_count":0,"update_count":765}
I20260812 06:19:32.775545 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling LogGCOp(0d1051b15a6f4ab4bfd6eb776482811b): free 12017947 bytes of WAL
I20260812 06:19:32.775863 24315 log_reader.cc:385] T 0d1051b15a6f4ab4bfd6eb776482811b: removed 1 log segments from log reader
I20260812 06:19:32.775938 24315 log.cc:1079] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d1051b15a6f4ab4bfd6eb776482811b/wal-000000039 (ops 187-191)
I20260812 06:19:32.779311 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: LogGCOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.004s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:32.779793 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=1.000000
I20260812 06:19:32.789172 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.009s	user 0.002s	sys 0.005s Metrics: {"bytes_written":1928327,"delete_count":0,"lbm_write_time_us":2947,"lbm_writes_lt_1ms":50,"reinsert_count":0,"update_count":235}
I20260812 06:19:32.789631 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling UndoDeltaBlockGCOp(0d1051b15a6f4ab4bfd6eb776482811b): 482 bytes on disk
I20260812 06:19:32.790015 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: UndoDeltaBlockGCOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:19:32.790529 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling MajorDeltaCompactionOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=1.000000
I20260812 06:19:32.960027 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: MajorDeltaCompactionOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.169s	user 0.141s	sys 0.028s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836320,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":600,"lbm_read_time_us":12293,"lbm_reads_lt_1ms":670,"lbm_write_time_us":34722,"lbm_writes_lt_1ms":643,"mutex_wait_us":71,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12672,"thread_start_us":76,"threads_started":1,"update_count":3000}
I20260812 06:19:32.961578 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=14.095187
I20260812 06:19:33.012233 24159 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.902s	user 1.848s	sys 0.166s
I20260812 06:19:33.015825 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.054s	user 0.032s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20858,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:33.016381 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=2.188937
I20260812 06:19:33.033784 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: FlushDeltaMemStoresOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.017s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6990,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":500}
I20260812 06:19:33.034336 24411 maintenance_manager.cc:419] P fb1906bd6e29475eb1bef3b14c02c754: Scheduling MajorDeltaCompactionOp(0d1051b15a6f4ab4bfd6eb776482811b): perf score=1.000000
I20260812 06:19:33.080307 24159 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.067s	user 0.003s	sys 0.000s
I20260812 06:19:33.081007 24159 tablet_server.cc:179] TabletServer@127.23.151.193:0 shutting down...
I20260812 06:19:33.160511 24315 maintenance_manager.cc:643] P fb1906bd6e29475eb1bef3b14c02c754: MajorDeltaCompactionOp(0d1051b15a6f4ab4bfd6eb776482811b) complete. Timing: real 0.126s	user 0.090s	sys 0.036s Metrics: {"cfile_cache_hit":369,"cfile_cache_hit_bytes":15097416,"cfile_cache_miss":163,"cfile_cache_miss_bytes":9636308,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":371,"lbm_read_time_us":5140,"lbm_reads_lt_1ms":195,"lbm_write_time_us":26588,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":155392,"update_count":2500}
I20260812 06:19:33.161209 24159 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:33.161646 24159 tablet_replica.cc:333] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754: stopping tablet replica
I20260812 06:19:33.161885 24159 raft_consensus.cc:2243] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:33.162138 24159 raft_consensus.cc:2272] T 0d1051b15a6f4ab4bfd6eb776482811b P fb1906bd6e29475eb1bef3b14c02c754 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:33.178512 24159 tablet_server.cc:196] TabletServer@127.23.151.193:0 shutdown complete.
I20260812 06:19:33.207675 24159 master.cc:562] Master@127.23.151.254:39195 shutting down...
I20260812 06:19:33.211728 24159 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 0b838f082fb44cbdb23394b2d5b45096 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:33.211931 24159 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 0b838f082fb44cbdb23394b2d5b45096 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:33.212018 24159 tablet_replica.cc:333] T 00000000000000000000000000000000 P 0b838f082fb44cbdb23394b2d5b45096: stopping tablet replica
I20260812 06:19:33.224382 24159 master.cc:584] Master@127.23.151.254:39195 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5486 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:33.313417 24159 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.23.151.254:41305
I20260812 06:19:33.313746 24159 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:33.315773 24458 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:33.315778 24455 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:33.315897 24159 server_base.cc:1061] running on GCE node
W20260812 06:19:33.316041 24456 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:33.316267 24159 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:33.316316 24159 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:33.316370 24159 hybrid_clock.cc:648] HybridClock initialized: now 1786515573316369 us; error 0 us; skew 500 ppm
I20260812 06:19:33.317231 24159 webserver.cc:533] Webserver started at http://127.23.151.254:33427/ using document root <none> and password file <none>
I20260812 06:19:33.317404 24159 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:33.317488 24159 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:33.317615 24159 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:33.318015 24159 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/master-0-root/instance:
uuid: "a987035ac9b747a7883448a7c1f3b26e"
format_stamp: "Formatted at 2026-08-12 06:19:33 on dist-test-slave-c12x"
I20260812 06:19:33.319689 24159 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:33.320729 24466 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:33.321008 24159 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:33.321075 24159 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/master-0-root
uuid: "a987035ac9b747a7883448a7c1f3b26e"
format_stamp: "Formatted at 2026-08-12 06:19:33 on dist-test-slave-c12x"
I20260812 06:19:33.321125 24159 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-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:33.329062 24159 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:33.329414 24159 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:33.333582 24159 rpc_server.cc:307] RPC server started. Bound to: 127.23.151.254:41305
I20260812 06:19:33.335536 24544 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.151.254:41305 every 8 connection(s)
I20260812 06:19:33.335678 24545 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:33.348392 24545 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a987035ac9b747a7883448a7c1f3b26e: Bootstrap starting.
I20260812 06:19:33.349401 24545 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P a987035ac9b747a7883448a7c1f3b26e: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:33.350558 24545 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a987035ac9b747a7883448a7c1f3b26e: No bootstrap required, opened a new log
I20260812 06:19:33.350993 24545 raft_consensus.cc:359] T 00000000000000000000000000000000 P a987035ac9b747a7883448a7c1f3b26e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a987035ac9b747a7883448a7c1f3b26e" member_type: VOTER }
I20260812 06:19:33.351095 24545 raft_consensus.cc:385] T 00000000000000000000000000000000 P a987035ac9b747a7883448a7c1f3b26e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:33.351119 24545 raft_consensus.cc:740] T 00000000000000000000000000000000 P a987035ac9b747a7883448a7c1f3b26e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a987035ac9b747a7883448a7c1f3b26e, State: Initialized, Role: FOLLOWER
I20260812 06:19:33.351279 24545 consensus_queue.cc:260] T 00000000000000000000000000000000 P a987035ac9b747a7883448a7c1f3b26e [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: "a987035ac9b747a7883448a7c1f3b26e" member_type: VOTER }
I20260812 06:19:33.351351 24545 raft_consensus.cc:399] T 00000000000000000000000000000000 P a987035ac9b747a7883448a7c1f3b26e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:33.351374 24545 raft_consensus.cc:493] T 00000000000000000000000000000000 P a987035ac9b747a7883448a7c1f3b26e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:33.351404 24545 raft_consensus.cc:3060] T 00000000000000000000000000000000 P a987035ac9b747a7883448a7c1f3b26e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:33.352249 24545 raft_consensus.cc:515] T 00000000000000000000000000000000 P a987035ac9b747a7883448a7c1f3b26e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a987035ac9b747a7883448a7c1f3b26e" member_type: VOTER }
I20260812 06:19:33.352394 24545 leader_election.cc:304] T 00000000000000000000000000000000 P a987035ac9b747a7883448a7c1f3b26e [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: a987035ac9b747a7883448a7c1f3b26e; no voters: 
I20260812 06:19:33.352639 24545 leader_election.cc:290] T 00000000000000000000000000000000 P a987035ac9b747a7883448a7c1f3b26e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:33.352890 24551 raft_consensus.cc:2804] T 00000000000000000000000000000000 P a987035ac9b747a7883448a7c1f3b26e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:33.353075 24551 raft_consensus.cc:697] T 00000000000000000000000000000000 P a987035ac9b747a7883448a7c1f3b26e [term 1 LEADER]: Becoming Leader. State: Replica: a987035ac9b747a7883448a7c1f3b26e, State: Running, Role: LEADER
I20260812 06:19:33.353157 24545 sys_catalog.cc:565] T 00000000000000000000000000000000 P a987035ac9b747a7883448a7c1f3b26e [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:33.353214 24551 consensus_queue.cc:237] T 00000000000000000000000000000000 P a987035ac9b747a7883448a7c1f3b26e [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: "a987035ac9b747a7883448a7c1f3b26e" member_type: VOTER }
I20260812 06:19:33.353677 24548 sys_catalog.cc:455] T 00000000000000000000000000000000 P a987035ac9b747a7883448a7c1f3b26e [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "a987035ac9b747a7883448a7c1f3b26e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a987035ac9b747a7883448a7c1f3b26e" member_type: VOTER } }
I20260812 06:19:33.353700 24554 sys_catalog.cc:455] T 00000000000000000000000000000000 P a987035ac9b747a7883448a7c1f3b26e [sys.catalog]: SysCatalogTable state changed. Reason: New leader a987035ac9b747a7883448a7c1f3b26e. Latest consensus state: current_term: 1 leader_uuid: "a987035ac9b747a7883448a7c1f3b26e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a987035ac9b747a7883448a7c1f3b26e" member_type: VOTER } }
I20260812 06:19:33.353786 24548 sys_catalog.cc:458] T 00000000000000000000000000000000 P a987035ac9b747a7883448a7c1f3b26e [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:33.353812 24554 sys_catalog.cc:458] T 00000000000000000000000000000000 P a987035ac9b747a7883448a7c1f3b26e [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:33.354521 24559 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:33.355201 24559 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:33.355392 24159 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:33.357288 24559 catalog_manager.cc:1383] Generated new cluster ID: 130952b5eefc4470ae8abfd1af3c6d18
I20260812 06:19:33.357385 24559 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:33.393105 24559 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:33.393896 24559 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:33.400575 24559 catalog_manager.cc:6092] T 00000000000000000000000000000000 P a987035ac9b747a7883448a7c1f3b26e: Generated new TSK 0
I20260812 06:19:33.400830 24559 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:33.420730 24159 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:33.423027 24580 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:33.423079 24579 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:33.423101 24582 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:33.423327 24159 server_base.cc:1061] running on GCE node
I20260812 06:19:33.423566 24159 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:33.423611 24159 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:33.423626 24159 hybrid_clock.cc:648] HybridClock initialized: now 1786515573423627 us; error 0 us; skew 500 ppm
I20260812 06:19:33.424417 24159 webserver.cc:533] Webserver started at http://127.23.151.193:41081/ using document root <none> and password file <none>
I20260812 06:19:33.424602 24159 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:33.424669 24159 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:33.424729 24159 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:33.425094 24159 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/instance:
uuid: "35d46461afc94480a4d925f54f29e245"
format_stamp: "Formatted at 2026-08-12 06:19:33 on dist-test-slave-c12x"
I20260812 06:19:33.426649 24159 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:33.427644 24592 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:33.427898 24159 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:33.427991 24159 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root
uuid: "35d46461afc94480a4d925f54f29e245"
format_stamp: "Formatted at 2026-08-12 06:19:33 on dist-test-slave-c12x"
I20260812 06:19:33.428094 24159 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-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:33.433562 24159 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:33.433954 24159 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:33.434271 24159 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:33.434749 24159 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:33.434810 24159 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:33.434871 24159 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:33.434906 24159 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:33.439324 24159 rpc_server.cc:307] RPC server started. Bound to: 127.23.151.193:40783
I20260812 06:19:33.439390 24693 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.151.193:40783 every 8 connection(s)
I20260812 06:19:33.449100 24694 heartbeater.cc:344] Connected to a master server at 127.23.151.254:41305
I20260812 06:19:33.449219 24694 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:33.449422 24694 heartbeater.cc:507] Master 127.23.151.254:41305 requested a full tablet report, sending...
I20260812 06:19:33.450099 24490 ts_manager.cc:194] Registered new tserver with Master: 35d46461afc94480a4d925f54f29e245 (127.23.151.193:40783)
I20260812 06:19:33.450783 24490 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:46688
I20260812 06:19:33.451148 24159 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011303256s
I20260812 06:19:33.458765 24490 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:46690:
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:33.467600 24641 tablet_service.cc:1511] Processing CreateTablet for tablet 0d0e1cd9f2c64608b694030e8f1c35a1 (DEFAULT_TABLE table=heavy-update-compaction-test [id=35ba760eb60a47b9a3b2b320741290fa]), partition=
I20260812 06:19:33.467890 24641 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 0d0e1cd9f2c64608b694030e8f1c35a1. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:33.469785 24713 tablet_bootstrap.cc:492] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Bootstrap starting.
I20260812 06:19:33.470651 24713 tablet_bootstrap.cc:654] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:33.471750 24713 tablet_bootstrap.cc:492] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: No bootstrap required, opened a new log
I20260812 06:19:33.471843 24713 ts_tablet_manager.cc:1403] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:33.472250 24713 raft_consensus.cc:359] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "35d46461afc94480a4d925f54f29e245" member_type: VOTER last_known_addr { host: "127.23.151.193" port: 40783 } }
I20260812 06:19:33.472332 24713 raft_consensus.cc:385] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:33.472393 24713 raft_consensus.cc:740] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 35d46461afc94480a4d925f54f29e245, State: Initialized, Role: FOLLOWER
I20260812 06:19:33.472553 24713 consensus_queue.cc:260] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245 [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: "35d46461afc94480a4d925f54f29e245" member_type: VOTER last_known_addr { host: "127.23.151.193" port: 40783 } }
I20260812 06:19:33.472651 24713 raft_consensus.cc:399] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:33.472699 24713 raft_consensus.cc:493] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:33.472756 24713 raft_consensus.cc:3060] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:33.473443 24713 raft_consensus.cc:515] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "35d46461afc94480a4d925f54f29e245" member_type: VOTER last_known_addr { host: "127.23.151.193" port: 40783 } }
I20260812 06:19:33.473604 24713 leader_election.cc:304] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245 [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: 35d46461afc94480a4d925f54f29e245; no voters: 
I20260812 06:19:33.473800 24713 leader_election.cc:290] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:33.473927 24715 raft_consensus.cc:2804] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:33.474151 24715 raft_consensus.cc:697] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245 [term 1 LEADER]: Becoming Leader. State: Replica: 35d46461afc94480a4d925f54f29e245, State: Running, Role: LEADER
I20260812 06:19:33.474174 24694 heartbeater.cc:499] Master 127.23.151.254:41305 was elected leader, sending a full tablet report...
I20260812 06:19:33.474152 24713 ts_tablet_manager.cc:1434] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:19:33.474323 24715 consensus_queue.cc:237] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245 [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: "35d46461afc94480a4d925f54f29e245" member_type: VOTER last_known_addr { host: "127.23.151.193" port: 40783 } }
I20260812 06:19:33.475612 24490 catalog_manager.cc:5719] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245 reported cstate change: term changed from 0 to 1, leader changed from <none> to 35d46461afc94480a4d925f54f29e245 (127.23.151.193). New cstate: current_term: 1 leader_uuid: "35d46461afc94480a4d925f54f29e245" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "35d46461afc94480a4d925f54f29e245" member_type: VOTER last_known_addr { host: "127.23.151.193" port: 40783 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:33.533986 24159 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.051s	user 0.011s	sys 0.012s
I20260812 06:19:33.690281 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushMRSOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=19.054940
I20260812 06:19:33.842865 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushMRSOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.152s	user 0.099s	sys 0.044s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":81,"dirs.run_cpu_time_us":191,"dirs.run_wall_time_us":900,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41360,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1500}
I20260812 06:19:33.843637 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling LogGCOp(0d0e1cd9f2c64608b694030e8f1c35a1): free 20743831 bytes of WAL
I20260812 06:19:33.843941 24598 log_reader.cc:385] T 0d0e1cd9f2c64608b694030e8f1c35a1: removed 2 log segments from log reader
I20260812 06:19:33.844019 24598 log.cc:1079] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d0e1cd9f2c64608b694030e8f1c35a1/wal-000000001 (ops 1-6)
I20260812 06:19:33.844074 24598 log.cc:1079] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d0e1cd9f2c64608b694030e8f1c35a1/wal-000000002 (ops 7-11)
I20260812 06:19:33.848575 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: LogGCOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.005s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:19:33.849139 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=2.188937
I20260812 06:19:33.862455 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.013s	user 0.000s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5218,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:33.863068 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling UndoDeltaBlockGCOp(0d0e1cd9f2c64608b694030e8f1c35a1): 20513815 bytes on disk
I20260812 06:19:33.863618 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: UndoDeltaBlockGCOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4}
I20260812 06:19:33.864106 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling MajorDeltaCompactionOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=1.000000
I20260812 06:19:33.999919 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: MajorDeltaCompactionOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.136s	user 0.112s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":499,"lbm_read_time_us":8822,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25082,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16640,"thread_start_us":368,"threads_started":5,"update_count":2000}
I20260812 06:19:34.000516 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=10.126437
I20260812 06:19:34.041837 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.041s	user 0.021s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16717,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:34.042317 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=2.188937
I20260812 06:19:34.052910 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4068,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:34.053442 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling MajorDeltaCompactionOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=1.000000
I20260812 06:19:34.177980 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: MajorDeltaCompactionOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.124s	user 0.088s	sys 0.036s 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":813,"lbm_read_time_us":8250,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22262,"lbm_writes_lt_1ms":443,"mutex_wait_us":324,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":49408,"update_count":2000}
I20260812 06:19:34.178632 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=10.126437
I20260812 06:19:34.226744 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.048s	user 0.025s	sys 0.018s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15679,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:34.227310 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=2.188937
I20260812 06:19:34.238308 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4298,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:34.238767 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling MajorDeltaCompactionOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=1.000000
I20260812 06:19:34.387641 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: MajorDeltaCompactionOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.149s	user 0.088s	sys 0.060s 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":1237,"lbm_read_time_us":10652,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24567,"lbm_writes_lt_1ms":443,"mutex_wait_us":295,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2000}
I20260812 06:19:34.388366 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=10.126437
I20260812 06:19:34.435564 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.047s	user 0.031s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":23814,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":300,"reinsert_count":0,"update_count":1500}
I20260812 06:19:34.436105 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=2.188937
I20260812 06:19:34.447485 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3907,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:34.448451 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling MajorDeltaCompactionOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=1.000000
I20260812 06:19:34.576098 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: MajorDeltaCompactionOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.127s	user 0.095s	sys 0.032s 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":284,"lbm_read_time_us":9030,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25074,"lbm_writes_lt_1ms":443,"mutex_wait_us":32,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:34.576776 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=10.126437
I20260812 06:19:34.616578 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.040s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14936,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:34.617050 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=2.188937
I20260812 06:19:34.627602 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4128,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:34.628209 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling MajorDeltaCompactionOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=1.000000
I20260812 06:19:34.763266 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: MajorDeltaCompactionOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.135s	user 0.107s	sys 0.025s 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":496,"lbm_read_time_us":8595,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26490,"lbm_writes_lt_1ms":443,"mutex_wait_us":19,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":2000}
I20260812 06:19:34.764003 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=10.126437
I20260812 06:19:34.801482 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.037s	user 0.023s	sys 0.011s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15672,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:34.801983 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling MajorDeltaCompactionOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=1.000000
I20260812 06:19:34.929438 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: MajorDeltaCompactionOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.127s	user 0.095s	sys 0.032s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16610740,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":419,"lbm_read_time_us":8318,"lbm_reads_lt_1ms":363,"lbm_write_time_us":20185,"lbm_writes_lt_1ms":343,"mutex_wait_us":81,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":1500}
I20260812 06:19:34.930023 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=10.126437
I20260812 06:19:34.972076 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.042s	user 0.020s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16175,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:34.972615 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=2.188937
I20260812 06:19:34.983144 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3910,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:34.983904 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling MajorDeltaCompactionOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=1.000000
I20260812 06:19:35.121122 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: MajorDeltaCompactionOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.137s	user 0.077s	sys 0.057s 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":228,"lbm_read_time_us":9949,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25768,"lbm_writes_lt_1ms":443,"mutex_wait_us":52,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":25728,"update_count":2000}
I20260812 06:19:35.121726 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=10.126437
I20260812 06:19:35.164776 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.043s	user 0.035s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18518,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:35.165448 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushMRSOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=1.000000
I20260812 06:19:35.215638 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushMRSOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.050s	user 0.026s	sys 0.004s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":89,"dirs.run_cpu_time_us":188,"dirs.run_wall_time_us":1119,"drs_written":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1588,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:35.216332 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling LogGCOp(0d0e1cd9f2c64608b694030e8f1c35a1): free 124710288 bytes of WAL
I20260812 06:19:35.216620 24598 log_reader.cc:385] T 0d0e1cd9f2c64608b694030e8f1c35a1: removed 12 log segments from log reader
I20260812 06:19:35.216696 24598 log.cc:1079] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d0e1cd9f2c64608b694030e8f1c35a1/wal-000000003 (ops 12-16)
I20260812 06:19:35.216747 24598 log.cc:1079] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d0e1cd9f2c64608b694030e8f1c35a1/wal-000000004 (ops 17-21)
I20260812 06:19:35.216801 24598 log.cc:1079] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d0e1cd9f2c64608b694030e8f1c35a1/wal-000000005 (ops 22-26)
I20260812 06:19:35.216856 24598 log.cc:1079] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d0e1cd9f2c64608b694030e8f1c35a1/wal-000000006 (ops 27-31)
I20260812 06:19:35.216895 24598 log.cc:1079] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d0e1cd9f2c64608b694030e8f1c35a1/wal-000000007 (ops 32-36)
I20260812 06:19:35.216936 24598 log.cc:1079] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d0e1cd9f2c64608b694030e8f1c35a1/wal-000000008 (ops 37-41)
I20260812 06:19:35.216975 24598 log.cc:1079] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d0e1cd9f2c64608b694030e8f1c35a1/wal-000000009 (ops 42-46)
I20260812 06:19:35.217015 24598 log.cc:1079] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d0e1cd9f2c64608b694030e8f1c35a1/wal-000000010 (ops 47-51)
I20260812 06:19:35.217064 24598 log.cc:1079] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d0e1cd9f2c64608b694030e8f1c35a1/wal-000000011 (ops 52-56)
I20260812 06:19:35.217101 24598 log.cc:1079] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d0e1cd9f2c64608b694030e8f1c35a1/wal-000000012 (ops 57-61)
I20260812 06:19:35.217144 24598 log.cc:1079] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d0e1cd9f2c64608b694030e8f1c35a1/wal-000000013 (ops 62-66)
I20260812 06:19:35.217182 24598 log.cc:1079] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d0e1cd9f2c64608b694030e8f1c35a1/wal-000000014 (ops 67-71)
I20260812 06:19:35.245149 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: LogGCOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.029s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:19:35.245632 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling UndoDeltaBlockGCOp(0d0e1cd9f2c64608b694030e8f1c35a1): 482 bytes on disk
I20260812 06:19:35.246114 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: UndoDeltaBlockGCOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:19:35.246755 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=7.149875
I20260812 06:19:35.267889 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.021s	user 0.017s	sys 0.003s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":8763,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:19:35.268356 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=2.188937
I20260812 06:19:35.285339 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.017s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5794,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:35.285816 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling MajorDeltaCompactionOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=1.000000
I20260812 06:19:35.468287 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: MajorDeltaCompactionOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.182s	user 0.155s	sys 0.025s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918207,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":362,"lbm_read_time_us":12102,"lbm_reads_lt_1ms":665,"lbm_write_time_us":38109,"lbm_writes_lt_1ms":643,"mutex_wait_us":272,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":71936,"thread_start_us":85,"threads_started":1,"update_count":3000}
I20260812 06:19:35.468766 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=14.095187
I20260812 06:19:35.521112 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.052s	user 0.022s	sys 0.028s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23235,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:35.521704 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=2.188937
I20260812 06:19:35.533138 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4284,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:35.533566 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling MajorDeltaCompactionOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=1.000000
I20260812 06:19:35.689857 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: MajorDeltaCompactionOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.156s	user 0.126s	sys 0.024s 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":210,"lbm_read_time_us":9784,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29375,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":46976,"update_count":2500}
I20260812 06:19:35.690475 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=14.095187
I20260812 06:19:35.749436 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.059s	user 0.042s	sys 0.008s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":23111,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:35.750043 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=2.188937
I20260812 06:19:35.760912 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4151,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:35.761704 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling MajorDeltaCompactionOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=1.000000
I20260812 06:19:35.916962 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: MajorDeltaCompactionOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.155s	user 0.123s	sys 0.032s 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":560,"lbm_read_time_us":12141,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28501,"lbm_writes_lt_1ms":543,"mutex_wait_us":61,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":2500}
I20260812 06:19:35.917685 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=10.126437
I20260812 06:19:35.953462 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.036s	user 0.030s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15052,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:35.954138 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=2.188937
I20260812 06:19:35.969735 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6072,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:35.970463 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling MajorDeltaCompactionOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=1.000000
I20260812 06:19:36.093819 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: MajorDeltaCompactionOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.123s	user 0.091s	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":368,"lbm_read_time_us":7773,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26237,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:19:36.094525 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=10.126437
I20260812 06:19:36.158224 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.064s	user 0.022s	sys 0.027s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19420,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:36.158878 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=3.181125
I20260812 06:19:36.185261 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.026s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":6626,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:36.185760 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=2.188937
I20260812 06:19:36.196355 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.010s	user 0.005s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3971,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:36.196866 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling MajorDeltaCompactionOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=1.000000
I20260812 06:19:36.383602 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: MajorDeltaCompactionOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.187s	user 0.136s	sys 0.050s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815791,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":289,"lbm_read_time_us":12239,"lbm_reads_lt_1ms":573,"lbm_write_time_us":33456,"lbm_writes_lt_1ms":543,"mutex_wait_us":49,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:36.384445 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=14.095187
I20260812 06:19:36.445878 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.061s	user 0.034s	sys 0.025s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":25910,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:19:36.446409 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=2.188937
I20260812 06:19:36.467762 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.021s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4621,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:36.468276 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=2.188937
I20260812 06:19:36.482882 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.014s	user 0.005s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5668,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:36.483562 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling MajorDeltaCompactionOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=1.000000
I20260812 06:19:36.681281 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: MajorDeltaCompactionOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.197s	user 0.125s	sys 0.072s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918215,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":622,"lbm_read_time_us":13929,"lbm_reads_lt_1ms":673,"lbm_write_time_us":32769,"lbm_writes_lt_1ms":643,"mutex_wait_us":28,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":3000}
I20260812 06:19:36.681964 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=14.095187
I20260812 06:19:36.723028 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.041s	user 0.022s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18443,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:36.723670 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushMRSOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=1.000000
I20260812 06:19:36.758949 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushMRSOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.035s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1316415,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":337,"dirs.run_wall_time_us":1260,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1919,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:36.759783 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling LogGCOp(0d0e1cd9f2c64608b694030e8f1c35a1): free 133024393 bytes of WAL
I20260812 06:19:36.760023 24598 log_reader.cc:385] T 0d0e1cd9f2c64608b694030e8f1c35a1: removed 13 log segments from log reader
I20260812 06:19:36.760087 24598 log.cc:1079] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d0e1cd9f2c64608b694030e8f1c35a1/wal-000000015 (ops 72-76)
I20260812 06:19:36.760170 24598 log.cc:1079] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d0e1cd9f2c64608b694030e8f1c35a1/wal-000000016 (ops 77-81)
I20260812 06:19:36.760211 24598 log.cc:1079] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d0e1cd9f2c64608b694030e8f1c35a1/wal-000000017 (ops 82-86)
I20260812 06:19:36.760255 24598 log.cc:1079] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d0e1cd9f2c64608b694030e8f1c35a1/wal-000000018 (ops 87-90)
I20260812 06:19:36.760299 24598 log.cc:1079] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d0e1cd9f2c64608b694030e8f1c35a1/wal-000000019 (ops 91-95)
I20260812 06:19:36.760341 24598 log.cc:1079] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d0e1cd9f2c64608b694030e8f1c35a1/wal-000000020 (ops 96-100)
I20260812 06:19:36.760383 24598 log.cc:1079] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d0e1cd9f2c64608b694030e8f1c35a1/wal-000000021 (ops 101-105)
I20260812 06:19:36.760425 24598 log.cc:1079] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d0e1cd9f2c64608b694030e8f1c35a1/wal-000000022 (ops 106-110)
I20260812 06:19:36.760468 24598 log.cc:1079] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d0e1cd9f2c64608b694030e8f1c35a1/wal-000000023 (ops 111-115)
I20260812 06:19:36.760509 24598 log.cc:1079] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d0e1cd9f2c64608b694030e8f1c35a1/wal-000000024 (ops 116-120)
I20260812 06:19:36.760562 24598 log.cc:1079] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d0e1cd9f2c64608b694030e8f1c35a1/wal-000000025 (ops 121-125)
I20260812 06:19:36.760604 24598 log.cc:1079] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d0e1cd9f2c64608b694030e8f1c35a1/wal-000000026 (ops 126-130)
I20260812 06:19:36.760646 24598 log.cc:1079] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d0e1cd9f2c64608b694030e8f1c35a1/wal-000000027 (ops 131-135)
I20260812 06:19:36.786325 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: LogGCOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.026s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:19:36.786736 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling UndoDeltaBlockGCOp(0d0e1cd9f2c64608b694030e8f1c35a1): 493 bytes on disk
I20260812 06:19:36.787179 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: UndoDeltaBlockGCOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:19:36.787802 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=6.157687
I20260812 06:19:36.815658 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.028s	user 0.015s	sys 0.012s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":12221,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:19:36.816141 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling LogGCOp(0d0e1cd9f2c64608b694030e8f1c35a1): free 12018006 bytes of WAL
I20260812 06:19:36.816370 24598 log_reader.cc:385] T 0d0e1cd9f2c64608b694030e8f1c35a1: removed 1 log segments from log reader
I20260812 06:19:36.816433 24598 log.cc:1079] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d0e1cd9f2c64608b694030e8f1c35a1/wal-000000028 (ops 136-140)
I20260812 06:19:36.819612 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: LogGCOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.003s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:19:36.819988 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling MajorDeltaCompactionOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=1.000000
I20260812 06:19:37.020843 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: MajorDeltaCompactionOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.201s	user 0.133s	sys 0.065s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918096,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":4592,"lbm_read_time_us":12100,"lbm_reads_lt_1ms":664,"lbm_write_time_us":34030,"lbm_writes_lt_1ms":643,"mutex_wait_us":1810,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":19200,"thread_start_us":87,"threads_started":1,"update_count":3000}
I20260812 06:19:37.021579 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=15.087375
I20260812 06:19:37.075309 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.054s	user 0.033s	sys 0.016s Metrics: {"bytes_written":16820144,"delete_count":0,"lbm_write_time_us":23979,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:37.075860 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=2.188937
I20260812 06:19:37.102128 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.026s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5084,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:37.102630 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=2.188937
I20260812 06:19:37.113199 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3990,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:37.113756 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling MajorDeltaCompactionOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=1.000000
I20260812 06:19:37.329536 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: MajorDeltaCompactionOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.215s	user 0.143s	sys 0.072s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918203,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":226,"lbm_read_time_us":13610,"lbm_reads_lt_1ms":673,"lbm_write_time_us":37863,"lbm_writes_lt_1ms":643,"mutex_wait_us":148,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":249856,"update_count":3000}
I20260812 06:19:37.330420 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=14.095187
I20260812 06:19:37.386668 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.056s	user 0.034s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23443,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:37.387820 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling MajorDeltaCompactionOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=1.000000
I20260812 06:19:37.539281 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: MajorDeltaCompactionOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.151s	user 0.098s	sys 0.041s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713153,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":446,"lbm_read_time_us":8727,"lbm_reads_lt_1ms":463,"lbm_write_time_us":23264,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:19:37.539904 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=14.095187
I20260812 06:19:37.594434 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.054s	user 0.018s	sys 0.033s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24059,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:37.595028 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=2.188937
I20260812 06:19:37.611382 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6242,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:37.620635 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling MajorDeltaCompactionOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=1.000000
I20260812 06:19:37.802124 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: MajorDeltaCompactionOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.181s	user 0.128s	sys 0.053s 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":925,"lbm_read_time_us":12213,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31110,"lbm_writes_lt_1ms":543,"mutex_wait_us":32,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2500}
I20260812 06:19:37.802800 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=14.095187
I20260812 06:19:37.848425 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.045s	user 0.018s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18242,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:37.848929 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=2.188937
I20260812 06:19:37.861506 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4411,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:37.862253 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling MajorDeltaCompactionOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=1.000000
I20260812 06:19:38.033185 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: MajorDeltaCompactionOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.171s	user 0.092s	sys 0.066s 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":304,"lbm_read_time_us":9655,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31525,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11904,"update_count":2500}
I20260812 06:19:38.033769 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=14.095187
I20260812 06:19:38.090443 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.057s	user 0.020s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21172,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:38.090981 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=2.188937
I20260812 06:19:38.104133 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5330,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.104822 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling MajorDeltaCompactionOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=1.000000
I20260812 06:19:38.290040 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: MajorDeltaCompactionOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.185s	user 0.142s	sys 0.028s 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":144,"lbm_read_time_us":10646,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33442,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19712,"update_count":2500}
I20260812 06:19:38.291944 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=10.126437
I20260812 06:19:38.322127 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.030s	user 0.018s	sys 0.009s Metrics: {"bytes_written":12512610,"delete_count":0,"lbm_write_time_us":13589,"lbm_writes_lt_1ms":308,"reinsert_count":0,"update_count":1525}
I20260812 06:19:38.322844 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=2.188937
I20260812 06:19:38.338657 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.016s	user 0.003s	sys 0.011s Metrics: {"bytes_written":3897534,"delete_count":0,"lbm_write_time_us":6140,"lbm_writes_lt_1ms":98,"reinsert_count":0,"update_count":475}
I20260812 06:19:38.339133 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushMRSOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=1.000000
I20260812 06:19:38.368391 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushMRSOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.029s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":79,"dirs.run_cpu_time_us":208,"dirs.run_wall_time_us":1345,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1570,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30,"spinlock_wait_cycles":8448}
I20260812 06:19:38.369096 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling LogGCOp(0d0e1cd9f2c64608b694030e8f1c35a1): free 120553636 bytes of WAL
I20260812 06:19:38.369330 24598 log_reader.cc:385] T 0d0e1cd9f2c64608b694030e8f1c35a1: removed 12 log segments from log reader
I20260812 06:19:38.369372 24598 log.cc:1079] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d0e1cd9f2c64608b694030e8f1c35a1/wal-000000029 (ops 141-145)
I20260812 06:19:38.369401 24598 log.cc:1079] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d0e1cd9f2c64608b694030e8f1c35a1/wal-000000030 (ops 146-150)
I20260812 06:19:38.369464 24598 log.cc:1079] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d0e1cd9f2c64608b694030e8f1c35a1/wal-000000031 (ops 151-155)
I20260812 06:19:38.369503 24598 log.cc:1079] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d0e1cd9f2c64608b694030e8f1c35a1/wal-000000032 (ops 156-160)
I20260812 06:19:38.369554 24598 log.cc:1079] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d0e1cd9f2c64608b694030e8f1c35a1/wal-000000033 (ops 161-165)
I20260812 06:19:38.369573 24598 log.cc:1079] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d0e1cd9f2c64608b694030e8f1c35a1/wal-000000034 (ops 166-170)
I20260812 06:19:38.369632 24598 log.cc:1079] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d0e1cd9f2c64608b694030e8f1c35a1/wal-000000035 (ops 171-174)
I20260812 06:19:38.369674 24598 log.cc:1079] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d0e1cd9f2c64608b694030e8f1c35a1/wal-000000036 (ops 175-179)
I20260812 06:19:38.369715 24598 log.cc:1079] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d0e1cd9f2c64608b694030e8f1c35a1/wal-000000037 (ops 180-184)
I20260812 06:19:38.369756 24598 log.cc:1079] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d0e1cd9f2c64608b694030e8f1c35a1/wal-000000038 (ops 185-188)
I20260812 06:19:38.369786 24598 log.cc:1079] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d0e1cd9f2c64608b694030e8f1c35a1/wal-000000039 (ops 189-193)
I20260812 06:19:38.369822 24598 log.cc:1079] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: Deleting log segment in path: /tmp/dist-test-taskUASWWT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515567816920-24159-0/minicluster-data/ts-0-root/wals/0d0e1cd9f2c64608b694030e8f1c35a1/wal-000000040 (ops 194-198)
I20260812 06:19:38.396941 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: LogGCOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:38.397526 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling UndoDeltaBlockGCOp(0d0e1cd9f2c64608b694030e8f1c35a1): 472 bytes on disk
I20260812 06:19:38.397979 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: UndoDeltaBlockGCOp(0d0e1cd9f2c64608b694030e8f1c35a1) 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:38.398633 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=4.173312
I20260812 06:19:38.405498 24159 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.871s	user 1.863s	sys 0.154s
I20260812 06:19:38.415819 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.017s	user 0.013s	sys 0.004s Metrics: {"bytes_written":6153870,"delete_count":0,"lbm_write_time_us":7401,"lbm_writes_lt_1ms":153,"reinsert_count":0,"update_count":750}
I20260812 06:19:38.416445 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=1.000000
I20260812 06:19:38.422823 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: FlushDeltaMemStoresOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.006s	user 0.001s	sys 0.004s Metrics: {"bytes_written":2051402,"delete_count":0,"lbm_write_time_us":2170,"lbm_writes_lt_1ms":53,"reinsert_count":0,"update_count":250}
I20260812 06:19:38.423336 24695 maintenance_manager.cc:419] P 35d46461afc94480a4d925f54f29e245: Scheduling MajorDeltaCompactionOp(0d0e1cd9f2c64608b694030e8f1c35a1): perf score=1.000000
I20260812 06:19:38.454663 24159 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.049s	user 0.001s	sys 0.000s
I20260812 06:19:38.455241 24159 tablet_server.cc:179] TabletServer@127.23.151.193:0 shutting down...
I20260812 06:19:38.551628 24598 maintenance_manager.cc:643] P 35d46461afc94480a4d925f54f29e245: MajorDeltaCompactionOp(0d0e1cd9f2c64608b694030e8f1c35a1) complete. Timing: real 0.128s	user 0.105s	sys 0.021s Metrics: {"cfile_cache_hit":402,"cfile_cache_hit_bytes":16409882,"cfile_cache_miss":232,"cfile_cache_miss_bytes":12508396,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":783,"lbm_read_time_us":5474,"lbm_reads_lt_1ms":268,"lbm_write_time_us":29425,"lbm_writes_lt_1ms":643,"mutex_wait_us":261,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7168,"thread_start_us":76,"threads_started":1,"update_count":3000}
I20260812 06:19:38.552835 24159 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:38.553102 24159 tablet_replica.cc:333] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245: stopping tablet replica
I20260812 06:19:38.553251 24159 raft_consensus.cc:2243] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:38.553421 24159 raft_consensus.cc:2272] T 0d0e1cd9f2c64608b694030e8f1c35a1 P 35d46461afc94480a4d925f54f29e245 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:38.567884 24159 tablet_server.cc:196] TabletServer@127.23.151.193:0 shutdown complete.
I20260812 06:19:38.602726 24159 master.cc:562] Master@127.23.151.254:41305 shutting down...
I20260812 06:19:38.606521 24159 raft_consensus.cc:2243] T 00000000000000000000000000000000 P a987035ac9b747a7883448a7c1f3b26e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:38.606740 24159 raft_consensus.cc:2272] T 00000000000000000000000000000000 P a987035ac9b747a7883448a7c1f3b26e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:38.606840 24159 tablet_replica.cc:333] T 00000000000000000000000000000000 P a987035ac9b747a7883448a7c1f3b26e: stopping tablet replica
I20260812 06:19:38.619789 24159 master.cc:584] Master@127.23.151.254:41305 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5389 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10876 ms total)

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