[==========] 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:17:26.079339 16120 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.15.190.62:41595
I20260812 06:17:26.080339 16120 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:17:26.080899 16120 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:26.086903 16134 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:17:26.087025 16130 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:17:26.087090 16120 server_base.cc:1061] running on GCE node
W20260812 06:17:26.087188 16128 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:17:26.087666 16120 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:26.087762 16120 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:17:26.087826 16120 hybrid_clock.cc:648] HybridClock initialized: now 1786515446087824 us; error 0 us; skew 500 ppm
I20260812 06:17:26.089428 16120 webserver.cc:533] Webserver started at http://127.15.190.62:41109/ using document root <none> and password file <none>
I20260812 06:17:26.089938 16120 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:26.089998 16120 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:26.090219 16120 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:26.091797 16120 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/master-0-root/instance:
uuid: "c94cdc9d6a3a4756a3150bb9fa2cf961"
format_stamp: "Formatted at 2026-08-12 06:17:26 on dist-test-slave-jlzn"
I20260812 06:17:26.095132 16120 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:26.097059 16141 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:17:26.098033 16120 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:17:26.098148 16120 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/master-0-root
uuid: "c94cdc9d6a3a4756a3150bb9fa2cf961"
format_stamp: "Formatted at 2026-08-12 06:17:26 on dist-test-slave-jlzn"
I20260812 06:17:26.098238 16120 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-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:17:26.125988 16120 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:26.126614 16120 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:17:26.126783 16120 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:26.134053 16120 rpc_server.cc:307] RPC server started. Bound to: 127.15.190.62:41595
I20260812 06:17:26.134052 16229 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.190.62:41595 every 8 connection(s)
I20260812 06:17:26.136214 16230 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:17:26.141352 16230 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c94cdc9d6a3a4756a3150bb9fa2cf961: Bootstrap starting.
I20260812 06:17:26.143518 16230 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P c94cdc9d6a3a4756a3150bb9fa2cf961: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:26.144399 16230 log.cc:826] T 00000000000000000000000000000000 P c94cdc9d6a3a4756a3150bb9fa2cf961: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:26.145943 16230 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c94cdc9d6a3a4756a3150bb9fa2cf961: No bootstrap required, opened a new log
I20260812 06:17:26.148533 16230 raft_consensus.cc:359] T 00000000000000000000000000000000 P c94cdc9d6a3a4756a3150bb9fa2cf961 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c94cdc9d6a3a4756a3150bb9fa2cf961" member_type: VOTER }
I20260812 06:17:26.148695 16230 raft_consensus.cc:385] T 00000000000000000000000000000000 P c94cdc9d6a3a4756a3150bb9fa2cf961 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:26.148748 16230 raft_consensus.cc:740] T 00000000000000000000000000000000 P c94cdc9d6a3a4756a3150bb9fa2cf961 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c94cdc9d6a3a4756a3150bb9fa2cf961, State: Initialized, Role: FOLLOWER
I20260812 06:17:26.149246 16230 consensus_queue.cc:260] T 00000000000000000000000000000000 P c94cdc9d6a3a4756a3150bb9fa2cf961 [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: "c94cdc9d6a3a4756a3150bb9fa2cf961" member_type: VOTER }
I20260812 06:17:26.149367 16230 raft_consensus.cc:399] T 00000000000000000000000000000000 P c94cdc9d6a3a4756a3150bb9fa2cf961 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:26.149408 16230 raft_consensus.cc:493] T 00000000000000000000000000000000 P c94cdc9d6a3a4756a3150bb9fa2cf961 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:26.149492 16230 raft_consensus.cc:3060] T 00000000000000000000000000000000 P c94cdc9d6a3a4756a3150bb9fa2cf961 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:26.150249 16230 raft_consensus.cc:515] T 00000000000000000000000000000000 P c94cdc9d6a3a4756a3150bb9fa2cf961 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c94cdc9d6a3a4756a3150bb9fa2cf961" member_type: VOTER }
I20260812 06:17:26.150617 16230 leader_election.cc:304] T 00000000000000000000000000000000 P c94cdc9d6a3a4756a3150bb9fa2cf961 [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: c94cdc9d6a3a4756a3150bb9fa2cf961; no voters: 
I20260812 06:17:26.150867 16230 leader_election.cc:290] T 00000000000000000000000000000000 P c94cdc9d6a3a4756a3150bb9fa2cf961 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:26.151002 16234 raft_consensus.cc:2804] T 00000000000000000000000000000000 P c94cdc9d6a3a4756a3150bb9fa2cf961 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:26.151213 16234 raft_consensus.cc:697] T 00000000000000000000000000000000 P c94cdc9d6a3a4756a3150bb9fa2cf961 [term 1 LEADER]: Becoming Leader. State: Replica: c94cdc9d6a3a4756a3150bb9fa2cf961, State: Running, Role: LEADER
I20260812 06:17:26.151624 16234 consensus_queue.cc:237] T 00000000000000000000000000000000 P c94cdc9d6a3a4756a3150bb9fa2cf961 [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: "c94cdc9d6a3a4756a3150bb9fa2cf961" member_type: VOTER }
I20260812 06:17:26.151741 16230 sys_catalog.cc:565] T 00000000000000000000000000000000 P c94cdc9d6a3a4756a3150bb9fa2cf961 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:26.153407 16235 sys_catalog.cc:455] T 00000000000000000000000000000000 P c94cdc9d6a3a4756a3150bb9fa2cf961 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "c94cdc9d6a3a4756a3150bb9fa2cf961" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c94cdc9d6a3a4756a3150bb9fa2cf961" member_type: VOTER } }
I20260812 06:17:26.153399 16236 sys_catalog.cc:455] T 00000000000000000000000000000000 P c94cdc9d6a3a4756a3150bb9fa2cf961 [sys.catalog]: SysCatalogTable state changed. Reason: New leader c94cdc9d6a3a4756a3150bb9fa2cf961. Latest consensus state: current_term: 1 leader_uuid: "c94cdc9d6a3a4756a3150bb9fa2cf961" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c94cdc9d6a3a4756a3150bb9fa2cf961" member_type: VOTER } }
I20260812 06:17:26.153525 16235 sys_catalog.cc:458] T 00000000000000000000000000000000 P c94cdc9d6a3a4756a3150bb9fa2cf961 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:26.153525 16236 sys_catalog.cc:458] T 00000000000000000000000000000000 P c94cdc9d6a3a4756a3150bb9fa2cf961 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:26.153882 16120 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:26.154022 16256 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:26.156096 16256 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:26.160418 16256 catalog_manager.cc:1383] Generated new cluster ID: 4242f113a5504d05a9744a17ce4346af
I20260812 06:17:26.160480 16256 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:26.178960 16256 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:26.179857 16256 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:26.188400 16256 catalog_manager.cc:6092] T 00000000000000000000000000000000 P c94cdc9d6a3a4756a3150bb9fa2cf961: Generated new TSK 0
I20260812 06:17:26.188988 16256 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:26.218585 16120 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:26.221146 16268 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:17:26.221197 16276 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:17:26.221298 16271 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:17:26.221410 16120 server_base.cc:1061] running on GCE node
I20260812 06:17:26.221714 16120 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:26.221776 16120 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:17:26.221804 16120 hybrid_clock.cc:648] HybridClock initialized: now 1786515446221804 us; error 0 us; skew 500 ppm
I20260812 06:17:26.222704 16120 webserver.cc:533] Webserver started at http://127.15.190.1:36785/ using document root <none> and password file <none>
I20260812 06:17:26.222868 16120 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:26.222929 16120 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:26.223003 16120 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:26.223433 16120 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root/instance:
uuid: "cba092a99f3048ac8d15384cf7cd14c9"
format_stamp: "Formatted at 2026-08-12 06:17:26 on dist-test-slave-jlzn"
I20260812 06:17:26.225220 16120 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:26.226250 16282 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:17:26.226485 16120 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:26.226545 16120 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root
uuid: "cba092a99f3048ac8d15384cf7cd14c9"
format_stamp: "Formatted at 2026-08-12 06:17:26 on dist-test-slave-jlzn"
I20260812 06:17:26.226611 16120 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-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:17:26.240329 16120 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:26.241057 16120 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:26.241539 16120 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:26.242376 16120 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:26.242429 16120 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:26.242476 16120 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:26.242506 16120 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:26.248708 16120 rpc_server.cc:307] RPC server started. Bound to: 127.15.190.1:45153
I20260812 06:17:26.248764 16381 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.190.1:45153 every 8 connection(s)
I20260812 06:17:26.258246 16383 heartbeater.cc:344] Connected to a master server at 127.15.190.62:41595
I20260812 06:17:26.258473 16383 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:26.258888 16383 heartbeater.cc:507] Master 127.15.190.62:41595 requested a full tablet report, sending...
I20260812 06:17:26.260197 16170 ts_manager.cc:194] Registered new tserver with Master: cba092a99f3048ac8d15384cf7cd14c9 (127.15.190.1:45153)
I20260812 06:17:26.260466 16120 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011163059s
I20260812 06:17:26.261345 16170 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:48252
I20260812 06:17:26.269409 16170 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:48258:
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:17:26.281865 16328 tablet_service.cc:1511] Processing CreateTablet for tablet 5ee65364998b4205a08287901ff13963 (DEFAULT_TABLE table=heavy-update-compaction-test [id=bdc069cb8cb34c4fb74ff4a2565a6218]), partition=
I20260812 06:17:26.282279 16328 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 5ee65364998b4205a08287901ff13963. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:26.284807 16400 tablet_bootstrap.cc:492] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Bootstrap starting.
I20260812 06:17:26.285856 16400 tablet_bootstrap.cc:654] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:26.287513 16400 tablet_bootstrap.cc:492] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: No bootstrap required, opened a new log
I20260812 06:17:26.287631 16400 ts_tablet_manager.cc:1403] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:26.288166 16400 raft_consensus.cc:359] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cba092a99f3048ac8d15384cf7cd14c9" member_type: VOTER last_known_addr { host: "127.15.190.1" port: 45153 } }
I20260812 06:17:26.288293 16400 raft_consensus.cc:385] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:26.288338 16400 raft_consensus.cc:740] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: cba092a99f3048ac8d15384cf7cd14c9, State: Initialized, Role: FOLLOWER
I20260812 06:17:26.288466 16400 consensus_queue.cc:260] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9 [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: "cba092a99f3048ac8d15384cf7cd14c9" member_type: VOTER last_known_addr { host: "127.15.190.1" port: 45153 } }
I20260812 06:17:26.288558 16400 raft_consensus.cc:399] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:26.288599 16400 raft_consensus.cc:493] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:26.288656 16400 raft_consensus.cc:3060] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:26.289553 16400 raft_consensus.cc:515] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cba092a99f3048ac8d15384cf7cd14c9" member_type: VOTER last_known_addr { host: "127.15.190.1" port: 45153 } }
I20260812 06:17:26.289733 16400 leader_election.cc:304] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9 [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: cba092a99f3048ac8d15384cf7cd14c9; no voters: 
I20260812 06:17:26.289986 16400 leader_election.cc:290] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:26.290082 16404 raft_consensus.cc:2804] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:26.290325 16404 raft_consensus.cc:697] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9 [term 1 LEADER]: Becoming Leader. State: Replica: cba092a99f3048ac8d15384cf7cd14c9, State: Running, Role: LEADER
I20260812 06:17:26.290325 16400 ts_tablet_manager.cc:1434] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:17:26.290544 16383 heartbeater.cc:499] Master 127.15.190.62:41595 was elected leader, sending a full tablet report...
I20260812 06:17:26.290540 16404 consensus_queue.cc:237] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9 [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: "cba092a99f3048ac8d15384cf7cd14c9" member_type: VOTER last_known_addr { host: "127.15.190.1" port: 45153 } }
I20260812 06:17:26.293144 16170 catalog_manager.cc:5719] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9 reported cstate change: term changed from 0 to 1, leader changed from <none> to cba092a99f3048ac8d15384cf7cd14c9 (127.15.190.1). New cstate: current_term: 1 leader_uuid: "cba092a99f3048ac8d15384cf7cd14c9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cba092a99f3048ac8d15384cf7cd14c9" member_type: VOTER last_known_addr { host: "127.15.190.1" port: 45153 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:26.348711 16120 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.046s	user 0.011s	sys 0.011s
I20260812 06:17:26.499691 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushMRSOp(5ee65364998b4205a08287901ff13963): perf score=23.023690
I20260812 06:17:26.683365 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushMRSOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.183s	user 0.134s	sys 0.039s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":53006,"compiler_manager_pool.run_cpu_time_us":176835,"compiler_manager_pool.run_wall_time_us":177040,"delete_count":0,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":210,"dirs.run_wall_time_us":844,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44891,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"thread_start_us":131,"threads_started":1,"update_count":1500}
I20260812 06:17:26.684528 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling LogGCOp(5ee65364998b4205a08287901ff13963): free 20743880 bytes of WAL
I20260812 06:17:26.684886 16287 log_reader.cc:385] T 5ee65364998b4205a08287901ff13963: removed 2 log segments from log reader
I20260812 06:17:26.684960 16287 log.cc:1079] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/5ee65364998b4205a08287901ff13963/wal-000000001 (ops 1-6)
I20260812 06:17:26.685024 16287 log.cc:1079] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/5ee65364998b4205a08287901ff13963/wal-000000002 (ops 7-11)
I20260812 06:17:26.688541 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: LogGCOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.004s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:26.688843 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling UndoDeltaBlockGCOp(5ee65364998b4205a08287901ff13963): 20513810 bytes on disk
I20260812 06:17:26.689368 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: UndoDeltaBlockGCOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:17:26.689790 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=2.188937
I20260812 06:17:26.700645 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3846,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.702312 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling MajorDeltaCompactionOp(5ee65364998b4205a08287901ff13963): perf score=1.000000
I20260812 06:17:26.841492 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: MajorDeltaCompactionOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.139s	user 0.078s	sys 0.061s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":432,"lbm_read_time_us":8279,"lbm_reads_lt_1ms":460,"lbm_write_time_us":23137,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"thread_start_us":296,"threads_started":5,"update_count":2000}
I20260812 06:17:26.841972 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=10.126437
I20260812 06:17:26.883065 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.041s	user 0.016s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14626,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:26.883559 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=2.188937
I20260812 06:17:26.893476 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.010s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3662,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.893956 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling MajorDeltaCompactionOp(5ee65364998b4205a08287901ff13963): perf score=1.000000
I20260812 06:17:27.013919 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: MajorDeltaCompactionOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.120s	user 0.096s	sys 0.024s 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":213,"lbm_read_time_us":7913,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22917,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:27.014436 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=10.126437
I20260812 06:17:27.050803 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.036s	user 0.020s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13049,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:27.051262 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=2.188937
I20260812 06:17:27.065846 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5402,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.066308 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling MajorDeltaCompactionOp(5ee65364998b4205a08287901ff13963): perf score=1.000000
I20260812 06:17:27.182698 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: MajorDeltaCompactionOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.116s	user 0.103s	sys 0.013s 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":255,"lbm_read_time_us":7533,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22374,"lbm_writes_lt_1ms":443,"mutex_wait_us":58,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2000}
I20260812 06:17:27.183284 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=10.126437
I20260812 06:17:27.223717 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.040s	user 0.016s	sys 0.018s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13587,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:27.224318 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=2.188937
I20260812 06:17:27.234490 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3811,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.234963 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling MajorDeltaCompactionOp(5ee65364998b4205a08287901ff13963): perf score=1.000000
I20260812 06:17:27.370252 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: MajorDeltaCompactionOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.135s	user 0.087s	sys 0.048s 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":730,"lbm_read_time_us":10413,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21782,"lbm_writes_lt_1ms":443,"mutex_wait_us":32,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:27.370736 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=10.126437
I20260812 06:17:27.411629 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.041s	user 0.020s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12802,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:27.412113 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=2.188937
I20260812 06:17:27.421679 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3611,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.422063 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling MajorDeltaCompactionOp(5ee65364998b4205a08287901ff13963): perf score=1.000000
I20260812 06:17:27.539938 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: MajorDeltaCompactionOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.118s	user 0.113s	sys 0.005s 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":264,"lbm_read_time_us":8641,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21751,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:27.540385 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=10.126437
I20260812 06:17:27.582327 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.042s	user 0.017s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":11795,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:27.582892 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=2.188937
I20260812 06:17:27.593080 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3657,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.593585 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling MajorDeltaCompactionOp(5ee65364998b4205a08287901ff13963): perf score=1.000000
I20260812 06:17:27.704315 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: MajorDeltaCompactionOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.111s	user 0.073s	sys 0.037s 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":95,"lbm_read_time_us":9010,"lbm_reads_lt_1ms":472,"lbm_write_time_us":19207,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":21632,"update_count":2000}
I20260812 06:17:27.704859 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=10.126437
I20260812 06:17:27.752496 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.047s	user 0.032s	sys 0.015s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":18981,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:27.753110 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=2.188937
I20260812 06:17:27.763943 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4033,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.764515 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushMRSOp(5ee65364998b4205a08287901ff13963): perf score=1.000000
I20260812 06:17:27.800232 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushMRSOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.036s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":176,"dirs.run_wall_time_us":1110,"drs_written":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1683,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28,"spinlock_wait_cycles":1920}
I20260812 06:17:27.801115 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling LogGCOp(5ee65364998b4205a08287901ff13963): free 115943172 bytes of WAL
I20260812 06:17:27.801383 16287 log_reader.cc:385] T 5ee65364998b4205a08287901ff13963: removed 11 log segments from log reader
I20260812 06:17:27.801441 16287 log.cc:1079] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/5ee65364998b4205a08287901ff13963/wal-000000003 (ops 12-16)
I20260812 06:17:27.801479 16287 log.cc:1079] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/5ee65364998b4205a08287901ff13963/wal-000000004 (ops 17-21)
I20260812 06:17:27.801512 16287 log.cc:1079] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/5ee65364998b4205a08287901ff13963/wal-000000005 (ops 22-26)
I20260812 06:17:27.801538 16287 log.cc:1079] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/5ee65364998b4205a08287901ff13963/wal-000000006 (ops 27-31)
I20260812 06:17:27.801568 16287 log.cc:1079] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/5ee65364998b4205a08287901ff13963/wal-000000007 (ops 32-36)
I20260812 06:17:27.801597 16287 log.cc:1079] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/5ee65364998b4205a08287901ff13963/wal-000000008 (ops 37-41)
I20260812 06:17:27.801648 16287 log.cc:1079] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/5ee65364998b4205a08287901ff13963/wal-000000009 (ops 42-46)
I20260812 06:17:27.801679 16287 log.cc:1079] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/5ee65364998b4205a08287901ff13963/wal-000000010 (ops 47-51)
I20260812 06:17:27.801704 16287 log.cc:1079] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/5ee65364998b4205a08287901ff13963/wal-000000011 (ops 52-56)
I20260812 06:17:27.801734 16287 log.cc:1079] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/5ee65364998b4205a08287901ff13963/wal-000000012 (ops 57-61)
I20260812 06:17:27.801764 16287 log.cc:1079] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/5ee65364998b4205a08287901ff13963/wal-000000013 (ops 62-66)
I20260812 06:17:27.819344 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: LogGCOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.018s	user 0.000s	sys 0.015s Metrics: {}
I20260812 06:17:27.819737 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling UndoDeltaBlockGCOp(5ee65364998b4205a08287901ff13963): 447 bytes on disk
I20260812 06:17:27.820233 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: UndoDeltaBlockGCOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:17:27.820734 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=2.188937
I20260812 06:17:27.842374 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.022s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4981,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.842820 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=2.188937
I20260812 06:17:27.852216 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.009s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3367,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.852705 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling MajorDeltaCompactionOp(5ee65364998b4205a08287901ff13963): perf score=1.000000
I20260812 06:17:28.038170 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: MajorDeltaCompactionOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.185s	user 0.117s	sys 0.067s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918334,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":359,"lbm_read_time_us":12486,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31322,"lbm_writes_lt_1ms":643,"mutex_wait_us":46,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8448,"thread_start_us":80,"threads_started":1,"update_count":3000}
I20260812 06:17:28.038794 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=14.095187
I20260812 06:17:28.079674 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.041s	user 0.013s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17505,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:28.080228 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling MajorDeltaCompactionOp(5ee65364998b4205a08287901ff13963): perf score=1.000000
I20260812 06:17:28.222568 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: MajorDeltaCompactionOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.142s	user 0.101s	sys 0.036s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":957,"lbm_read_time_us":9631,"lbm_reads_lt_1ms":463,"lbm_write_time_us":22198,"lbm_writes_lt_1ms":443,"mutex_wait_us":477,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":2000}
I20260812 06:17:28.223014 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=11.118625
I20260812 06:17:28.254431 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.031s	user 0.008s	sys 0.019s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12913,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:28.254844 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=2.188937
I20260812 06:17:28.278263 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.023s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4734,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.278789 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=2.188937
I20260812 06:17:28.292896 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.014s	user 0.008s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5085,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:28.293548 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling MajorDeltaCompactionOp(5ee65364998b4205a08287901ff13963): perf score=1.000000
I20260812 06:17:28.467285 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: MajorDeltaCompactionOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.173s	user 0.115s	sys 0.049s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":747,"lbm_read_time_us":9907,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27382,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:17:28.467775 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=14.095187
I20260812 06:17:28.514959 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.047s	user 0.022s	sys 0.017s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18723,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:28.515395 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=2.188937
I20260812 06:17:28.525359 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3551,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.525936 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling MajorDeltaCompactionOp(5ee65364998b4205a08287901ff13963): perf score=1.000000
I20260812 06:17:28.673852 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: MajorDeltaCompactionOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.147s	user 0.089s	sys 0.055s 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":83,"lbm_read_time_us":8991,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28164,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:17:28.674412 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=11.118625
I20260812 06:17:28.706347 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.032s	user 0.013s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14749,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:28.706923 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=2.188937
I20260812 06:17:28.727102 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.020s	user 0.011s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4104,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:28.727598 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=2.188937
I20260812 06:17:28.742012 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5249,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.742517 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling MajorDeltaCompactionOp(5ee65364998b4205a08287901ff13963): perf score=1.000000
I20260812 06:17:28.884418 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: MajorDeltaCompactionOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.142s	user 0.122s	sys 0.019s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815793,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":263,"lbm_read_time_us":10998,"lbm_reads_lt_1ms":573,"lbm_write_time_us":25809,"lbm_writes_lt_1ms":543,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":80640,"update_count":2500}
I20260812 06:17:28.884913 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=11.118625
I20260812 06:17:28.918277 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.033s	user 0.022s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13789,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:28.918834 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=2.188937
I20260812 06:17:28.944947 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.026s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4770,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:28.945492 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=2.188937
I20260812 06:17:28.956744 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.011s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3772,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:28.957360 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling MajorDeltaCompactionOp(5ee65364998b4205a08287901ff13963): perf score=1.000000
I20260812 06:17:29.098647 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: MajorDeltaCompactionOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.141s	user 0.111s	sys 0.028s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815793,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":614,"lbm_read_time_us":10715,"lbm_reads_lt_1ms":573,"lbm_write_time_us":24553,"lbm_writes_lt_1ms":543,"mutex_wait_us":252,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2500}
I20260812 06:17:29.099331 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=11.118625
I20260812 06:17:29.148669 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.049s	user 0.021s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13631,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:29.149322 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=2.188937
I20260812 06:17:29.160463 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3844,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.160908 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=2.188937
I20260812 06:17:29.173362 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4591,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:29.173820 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushMRSOp(5ee65364998b4205a08287901ff13963): perf score=1.000000
I20260812 06:17:29.203473 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushMRSOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.029s	user 0.021s	sys 0.004s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":230,"dirs.run_wall_time_us":1107,"drs_written":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1588,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:29.204326 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling LogGCOp(5ee65364998b4205a08287901ff13963): free 133024372 bytes of WAL
I20260812 06:17:29.204566 16287 log_reader.cc:385] T 5ee65364998b4205a08287901ff13963: removed 13 log segments from log reader
I20260812 06:17:29.204617 16287 log.cc:1079] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/5ee65364998b4205a08287901ff13963/wal-000000014 (ops 67-71)
I20260812 06:17:29.204649 16287 log.cc:1079] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/5ee65364998b4205a08287901ff13963/wal-000000015 (ops 72-76)
I20260812 06:17:29.204669 16287 log.cc:1079] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/5ee65364998b4205a08287901ff13963/wal-000000016 (ops 77-81)
I20260812 06:17:29.204700 16287 log.cc:1079] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/5ee65364998b4205a08287901ff13963/wal-000000017 (ops 82-86)
I20260812 06:17:29.204732 16287 log.cc:1079] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/5ee65364998b4205a08287901ff13963/wal-000000018 (ops 87-91)
I20260812 06:17:29.204766 16287 log.cc:1079] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/5ee65364998b4205a08287901ff13963/wal-000000019 (ops 92-96)
I20260812 06:17:29.204797 16287 log.cc:1079] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/5ee65364998b4205a08287901ff13963/wal-000000020 (ops 97-101)
I20260812 06:17:29.204829 16287 log.cc:1079] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/5ee65364998b4205a08287901ff13963/wal-000000021 (ops 102-106)
I20260812 06:17:29.204861 16287 log.cc:1079] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/5ee65364998b4205a08287901ff13963/wal-000000022 (ops 107-110)
I20260812 06:17:29.204892 16287 log.cc:1079] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/5ee65364998b4205a08287901ff13963/wal-000000023 (ops 111-115)
I20260812 06:17:29.204924 16287 log.cc:1079] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/5ee65364998b4205a08287901ff13963/wal-000000024 (ops 116-120)
I20260812 06:17:29.204954 16287 log.cc:1079] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/5ee65364998b4205a08287901ff13963/wal-000000025 (ops 121-125)
I20260812 06:17:29.204985 16287 log.cc:1079] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/5ee65364998b4205a08287901ff13963/wal-000000026 (ops 126-130)
I20260812 06:17:29.225071 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: LogGCOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.021s	user 0.000s	sys 0.019s Metrics: {}
I20260812 06:17:29.225507 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=2.188937
I20260812 06:17:29.240749 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.015s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3807,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.241210 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=2.188937
I20260812 06:17:29.250725 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3547,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.251276 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling UndoDeltaBlockGCOp(5ee65364998b4205a08287901ff13963): 482 bytes on disk
I20260812 06:17:29.251734 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: UndoDeltaBlockGCOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:17:29.252880 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling MajorDeltaCompactionOp(5ee65364998b4205a08287901ff13963): perf score=1.000000
I20260812 06:17:29.416605 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: MajorDeltaCompactionOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.163s	user 0.136s	sys 0.027s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020856,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":417,"lbm_read_time_us":11657,"lbm_reads_lt_1ms":775,"lbm_write_time_us":33206,"lbm_writes_lt_1ms":743,"mutex_wait_us":20,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":11648,"thread_start_us":72,"threads_started":1,"update_count":3500}
I20260812 06:17:29.417155 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=14.095187
I20260812 06:17:29.458351 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.041s	user 0.021s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":16835,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:29.460131 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=3.181125
I20260812 06:17:29.485110 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.022s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4512904,"delete_count":0,"lbm_write_time_us":5955,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:29.485538 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=2.188937
I20260812 06:17:29.494589 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3367,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:29.494977 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling MajorDeltaCompactionOp(5ee65364998b4205a08287901ff13963): perf score=1.000000
I20260812 06:17:29.650708 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: MajorDeltaCompactionOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.156s	user 0.133s	sys 0.019s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918206,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":759,"lbm_read_time_us":11678,"lbm_reads_lt_1ms":673,"lbm_write_time_us":31250,"lbm_writes_lt_1ms":643,"mutex_wait_us":27,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:17:29.651168 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=14.095187
I20260812 06:17:29.698840 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.047s	user 0.025s	sys 0.019s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":23066,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:17:29.699389 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=2.188937
I20260812 06:17:29.720225 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.021s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5112,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.720661 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling MajorDeltaCompactionOp(5ee65364998b4205a08287901ff13963): perf score=1.000000
I20260812 06:17:29.863487 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: MajorDeltaCompactionOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.143s	user 0.092s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815686,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":153,"lbm_read_time_us":8480,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29107,"lbm_writes_lt_1ms":543,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:17:29.864089 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=14.095187
I20260812 06:17:29.917701 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.053s	user 0.032s	sys 0.016s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":21712,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:29.918201 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=2.188937
I20260812 06:17:29.928797 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3641,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.929303 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling MajorDeltaCompactionOp(5ee65364998b4205a08287901ff13963): perf score=1.000000
I20260812 06:17:30.086689 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: MajorDeltaCompactionOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.157s	user 0.116s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":217,"lbm_read_time_us":10524,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31495,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:30.087318 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=14.095187
I20260812 06:17:30.125270 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.038s	user 0.033s	sys 0.004s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":16802,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:30.125840 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling MajorDeltaCompactionOp(5ee65364998b4205a08287901ff13963): perf score=1.000000
I20260812 06:17:30.257655 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: MajorDeltaCompactionOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.132s	user 0.093s	sys 0.039s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713153,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":62,"lbm_read_time_us":9530,"lbm_reads_lt_1ms":467,"lbm_write_time_us":21947,"lbm_writes_lt_1ms":443,"mutex_wait_us":34,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":2000}
I20260812 06:17:30.258338 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=10.126437
I20260812 06:17:30.293063 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.035s	user 0.017s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14870,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:30.293606 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=2.188937
I20260812 06:17:30.307967 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.014s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5646,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.308457 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling MajorDeltaCompactionOp(5ee65364998b4205a08287901ff13963): perf score=1.000000
I20260812 06:17:30.427490 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: MajorDeltaCompactionOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.119s	user 0.093s	sys 0.024s 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":141,"lbm_read_time_us":8433,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22672,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:30.428062 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=10.126437
I20260812 06:17:30.469750 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.041s	user 0.026s	sys 0.006s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15228,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:30.470341 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=2.188937
I20260812 06:17:30.480957 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.010s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3966,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.481609 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushMRSOp(5ee65364998b4205a08287901ff13963): perf score=1.000000
I20260812 06:17:30.513880 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushMRSOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.032s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":201,"dirs.run_wall_time_us":1294,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1642,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:30.514559 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling LogGCOp(5ee65364998b4205a08287901ff13963): free 121006692 bytes of WAL
I20260812 06:17:30.514784 16287 log_reader.cc:385] T 5ee65364998b4205a08287901ff13963: removed 12 log segments from log reader
I20260812 06:17:30.514833 16287 log.cc:1079] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/5ee65364998b4205a08287901ff13963/wal-000000027 (ops 131-135)
I20260812 06:17:30.514863 16287 log.cc:1079] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/5ee65364998b4205a08287901ff13963/wal-000000028 (ops 136-140)
I20260812 06:17:30.514894 16287 log.cc:1079] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/5ee65364998b4205a08287901ff13963/wal-000000029 (ops 141-145)
I20260812 06:17:30.514925 16287 log.cc:1079] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/5ee65364998b4205a08287901ff13963/wal-000000030 (ops 146-150)
I20260812 06:17:30.514957 16287 log.cc:1079] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/5ee65364998b4205a08287901ff13963/wal-000000031 (ops 151-155)
I20260812 06:17:30.515005 16287 log.cc:1079] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/5ee65364998b4205a08287901ff13963/wal-000000032 (ops 156-160)
I20260812 06:17:30.515040 16287 log.cc:1079] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/5ee65364998b4205a08287901ff13963/wal-000000033 (ops 161-165)
I20260812 06:17:30.515064 16287 log.cc:1079] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/5ee65364998b4205a08287901ff13963/wal-000000034 (ops 166-170)
I20260812 06:17:30.515095 16287 log.cc:1079] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/5ee65364998b4205a08287901ff13963/wal-000000035 (ops 171-174)
I20260812 06:17:30.515136 16287 log.cc:1079] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/5ee65364998b4205a08287901ff13963/wal-000000036 (ops 175-179)
I20260812 06:17:30.515169 16287 log.cc:1079] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/5ee65364998b4205a08287901ff13963/wal-000000037 (ops 180-184)
I20260812 06:17:30.515200 16287 log.cc:1079] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/5ee65364998b4205a08287901ff13963/wal-000000038 (ops 185-189)
I20260812 06:17:30.537014 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: LogGCOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.022s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:17:30.537429 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling UndoDeltaBlockGCOp(5ee65364998b4205a08287901ff13963): 472 bytes on disk
I20260812 06:17:30.537854 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: UndoDeltaBlockGCOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:17:30.538393 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=3.181125
I20260812 06:17:30.550040 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4512904,"delete_count":0,"lbm_write_time_us":4061,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:30.550513 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=2.188937
I20260812 06:17:30.560293 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3423,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:30.560729 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling MajorDeltaCompactionOp(5ee65364998b4205a08287901ff13963): perf score=1.000000
I20260812 06:17:30.726218 16120 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.377s	user 1.626s	sys 0.107s
I20260812 06:17:30.728353 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: MajorDeltaCompactionOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.167s	user 0.120s	sys 0.044s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918325,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":136,"lbm_read_time_us":12708,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32744,"lbm_writes_lt_1ms":643,"mutex_wait_us":52,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":21632,"thread_start_us":71,"threads_started":1,"update_count":3000}
I20260812 06:17:30.728772 16385 maintenance_manager.cc:419] P cba092a99f3048ac8d15384cf7cd14c9: Scheduling FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963): perf score=14.095187
I20260812 06:17:30.753212 16120 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.026s	user 0.001s	sys 0.001s
I20260812 06:17:30.753834 16120 tablet_server.cc:179] TabletServer@127.15.190.1:0 shutting down...
I20260812 06:17:30.764554 16287 maintenance_manager.cc:643] P cba092a99f3048ac8d15384cf7cd14c9: FlushDeltaMemStoresOp(5ee65364998b4205a08287901ff13963) complete. Timing: real 0.036s	user 0.019s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":15693,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:30.765098 16120 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:30.765461 16120 tablet_replica.cc:333] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9: stopping tablet replica
I20260812 06:17:30.766250 16120 raft_consensus.cc:2243] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:30.766475 16120 raft_consensus.cc:2272] T 5ee65364998b4205a08287901ff13963 P cba092a99f3048ac8d15384cf7cd14c9 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:30.780880 16120 tablet_server.cc:196] TabletServer@127.15.190.1:0 shutdown complete.
I20260812 06:17:30.785246 16120 master.cc:562] Master@127.15.190.62:41595 shutting down...
I20260812 06:17:30.788305 16120 raft_consensus.cc:2243] T 00000000000000000000000000000000 P c94cdc9d6a3a4756a3150bb9fa2cf961 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:30.788451 16120 raft_consensus.cc:2272] T 00000000000000000000000000000000 P c94cdc9d6a3a4756a3150bb9fa2cf961 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:30.788502 16120 tablet_replica.cc:333] T 00000000000000000000000000000000 P c94cdc9d6a3a4756a3150bb9fa2cf961: stopping tablet replica
I20260812 06:17:30.800666 16120 master.cc:584] Master@127.15.190.62:41595 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (4791 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:30.881670 16120 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.15.190.62:40401
I20260812 06:17:30.882088 16120 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:30.883988 16440 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:17:30.884055 16438 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:17:30.884137 16437 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:17:30.884312 16120 server_base.cc:1061] running on GCE node
I20260812 06:17:30.884469 16120 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:30.884511 16120 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:17:30.884531 16120 hybrid_clock.cc:648] HybridClock initialized: now 1786515450884530 us; error 0 us; skew 500 ppm
I20260812 06:17:30.885383 16120 webserver.cc:533] Webserver started at http://127.15.190.62:43181/ using document root <none> and password file <none>
I20260812 06:17:30.885542 16120 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:30.885591 16120 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:30.885679 16120 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:30.886061 16120 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/master-0-root/instance:
uuid: "f797b795626441e88096b8210e236296"
format_stamp: "Formatted at 2026-08-12 06:17:30 on dist-test-slave-jlzn"
I20260812 06:17:30.887496 16120 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:30.888509 16447 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:17:30.888736 16120 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:30.888804 16120 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/master-0-root
uuid: "f797b795626441e88096b8210e236296"
format_stamp: "Formatted at 2026-08-12 06:17:30 on dist-test-slave-jlzn"
I20260812 06:17:30.888876 16120 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-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:17:30.904343 16120 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:30.904755 16120 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:30.908754 16120 rpc_server.cc:307] RPC server started. Bound to: 127.15.190.62:40401
I20260812 06:17:30.909179 16542 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.190.62:40401 every 8 connection(s)
I20260812 06:17:30.909760 16544 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:17:30.911532 16544 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f797b795626441e88096b8210e236296: Bootstrap starting.
I20260812 06:17:30.912343 16544 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P f797b795626441e88096b8210e236296: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:30.913286 16544 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f797b795626441e88096b8210e236296: No bootstrap required, opened a new log
I20260812 06:17:30.913669 16544 raft_consensus.cc:359] T 00000000000000000000000000000000 P f797b795626441e88096b8210e236296 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f797b795626441e88096b8210e236296" member_type: VOTER }
I20260812 06:17:30.913757 16544 raft_consensus.cc:385] T 00000000000000000000000000000000 P f797b795626441e88096b8210e236296 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:30.913793 16544 raft_consensus.cc:740] T 00000000000000000000000000000000 P f797b795626441e88096b8210e236296 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f797b795626441e88096b8210e236296, State: Initialized, Role: FOLLOWER
I20260812 06:17:30.913935 16544 consensus_queue.cc:260] T 00000000000000000000000000000000 P f797b795626441e88096b8210e236296 [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: "f797b795626441e88096b8210e236296" member_type: VOTER }
I20260812 06:17:30.914021 16544 raft_consensus.cc:399] T 00000000000000000000000000000000 P f797b795626441e88096b8210e236296 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:30.914062 16544 raft_consensus.cc:493] T 00000000000000000000000000000000 P f797b795626441e88096b8210e236296 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:30.914110 16544 raft_consensus.cc:3060] T 00000000000000000000000000000000 P f797b795626441e88096b8210e236296 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:30.914794 16544 raft_consensus.cc:515] T 00000000000000000000000000000000 P f797b795626441e88096b8210e236296 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f797b795626441e88096b8210e236296" member_type: VOTER }
I20260812 06:17:30.914913 16544 leader_election.cc:304] T 00000000000000000000000000000000 P f797b795626441e88096b8210e236296 [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: f797b795626441e88096b8210e236296; no voters: 
I20260812 06:17:30.915086 16544 leader_election.cc:290] T 00000000000000000000000000000000 P f797b795626441e88096b8210e236296 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:30.915195 16550 raft_consensus.cc:2804] T 00000000000000000000000000000000 P f797b795626441e88096b8210e236296 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:30.915398 16550 raft_consensus.cc:697] T 00000000000000000000000000000000 P f797b795626441e88096b8210e236296 [term 1 LEADER]: Becoming Leader. State: Replica: f797b795626441e88096b8210e236296, State: Running, Role: LEADER
I20260812 06:17:30.915529 16544 sys_catalog.cc:565] T 00000000000000000000000000000000 P f797b795626441e88096b8210e236296 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:30.915535 16550 consensus_queue.cc:237] T 00000000000000000000000000000000 P f797b795626441e88096b8210e236296 [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: "f797b795626441e88096b8210e236296" member_type: VOTER }
I20260812 06:17:30.916018 16551 sys_catalog.cc:455] T 00000000000000000000000000000000 P f797b795626441e88096b8210e236296 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "f797b795626441e88096b8210e236296" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f797b795626441e88096b8210e236296" member_type: VOTER } }
I20260812 06:17:30.916040 16553 sys_catalog.cc:455] T 00000000000000000000000000000000 P f797b795626441e88096b8210e236296 [sys.catalog]: SysCatalogTable state changed. Reason: New leader f797b795626441e88096b8210e236296. Latest consensus state: current_term: 1 leader_uuid: "f797b795626441e88096b8210e236296" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f797b795626441e88096b8210e236296" member_type: VOTER } }
I20260812 06:17:30.916180 16551 sys_catalog.cc:458] T 00000000000000000000000000000000 P f797b795626441e88096b8210e236296 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:30.916198 16553 sys_catalog.cc:458] T 00000000000000000000000000000000 P f797b795626441e88096b8210e236296 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:30.916642 16563 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:30.917395 16563 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:30.917570 16120 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:30.919137 16563 catalog_manager.cc:1383] Generated new cluster ID: f02a088d28514d518048ad74cb4bde1d
I20260812 06:17:30.919200 16563 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:30.927230 16563 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:30.927743 16563 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:30.932423 16563 catalog_manager.cc:6092] T 00000000000000000000000000000000 P f797b795626441e88096b8210e236296: Generated new TSK 0
I20260812 06:17:30.932582 16563 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:30.933634 16120 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:30.935318 16587 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:17:30.935431 16585 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:17:30.935489 16591 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:17:30.935664 16120 server_base.cc:1061] running on GCE node
I20260812 06:17:30.935865 16120 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:30.935904 16120 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:17:30.935928 16120 hybrid_clock.cc:648] HybridClock initialized: now 1786515450935928 us; error 0 us; skew 500 ppm
I20260812 06:17:30.936728 16120 webserver.cc:533] Webserver started at http://127.15.190.1:34393/ using document root <none> and password file <none>
I20260812 06:17:30.936879 16120 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:30.936924 16120 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:30.936997 16120 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:30.937348 16120 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root/instance:
uuid: "51eea6fc722848c8a9b87f2a8af03a1d"
format_stamp: "Formatted at 2026-08-12 06:17:30 on dist-test-slave-jlzn"
I20260812 06:17:30.938738 16120 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:17:30.939591 16597 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:17:30.939787 16120 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:30.939885 16120 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root
uuid: "51eea6fc722848c8a9b87f2a8af03a1d"
format_stamp: "Formatted at 2026-08-12 06:17:30 on dist-test-slave-jlzn"
I20260812 06:17:30.939952 16120 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-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:17:30.954829 16120 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:30.955222 16120 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:30.955518 16120 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:30.956007 16120 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:30.956048 16120 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:30.956091 16120 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:30.956120 16120 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:30.960273 16120 rpc_server.cc:307] RPC server started. Bound to: 127.15.190.1:36213
I20260812 06:17:30.960338 16698 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.15.190.1:36213 every 8 connection(s)
I20260812 06:17:30.967602 16700 heartbeater.cc:344] Connected to a master server at 127.15.190.62:40401
I20260812 06:17:30.967711 16700 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:30.967947 16700 heartbeater.cc:507] Master 127.15.190.62:40401 requested a full tablet report, sending...
I20260812 06:17:30.968541 16478 ts_manager.cc:194] Registered new tserver with Master: 51eea6fc722848c8a9b87f2a8af03a1d (127.15.190.1:36213)
I20260812 06:17:30.969246 16478 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:33104
I20260812 06:17:30.969358 16120 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.008697659s
I20260812 06:17:30.975719 16478 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:33108:
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:17:30.984781 16638 tablet_service.cc:1511] Processing CreateTablet for tablet ce1de6da81504daf921963209840fdf3 (DEFAULT_TABLE table=heavy-update-compaction-test [id=42f2bedcc3c743c4898fb79db029fe14]), partition=
I20260812 06:17:30.985045 16638 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet ce1de6da81504daf921963209840fdf3. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:30.986929 16716 tablet_bootstrap.cc:492] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Bootstrap starting.
I20260812 06:17:30.987721 16716 tablet_bootstrap.cc:654] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:30.988737 16716 tablet_bootstrap.cc:492] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: No bootstrap required, opened a new log
I20260812 06:17:30.988811 16716 ts_tablet_manager.cc:1403] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:17:30.989171 16716 raft_consensus.cc:359] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "51eea6fc722848c8a9b87f2a8af03a1d" member_type: VOTER last_known_addr { host: "127.15.190.1" port: 36213 } }
I20260812 06:17:30.989252 16716 raft_consensus.cc:385] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:30.989277 16716 raft_consensus.cc:740] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 51eea6fc722848c8a9b87f2a8af03a1d, State: Initialized, Role: FOLLOWER
I20260812 06:17:30.989382 16716 consensus_queue.cc:260] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d [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: "51eea6fc722848c8a9b87f2a8af03a1d" member_type: VOTER last_known_addr { host: "127.15.190.1" port: 36213 } }
I20260812 06:17:30.989461 16716 raft_consensus.cc:399] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:30.989485 16716 raft_consensus.cc:493] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:30.989533 16716 raft_consensus.cc:3060] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:30.990299 16716 raft_consensus.cc:515] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "51eea6fc722848c8a9b87f2a8af03a1d" member_type: VOTER last_known_addr { host: "127.15.190.1" port: 36213 } }
I20260812 06:17:30.990417 16716 leader_election.cc:304] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d [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: 51eea6fc722848c8a9b87f2a8af03a1d; no voters: 
I20260812 06:17:30.990561 16716 leader_election.cc:290] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:30.990662 16718 raft_consensus.cc:2804] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:30.990839 16716 ts_tablet_manager.cc:1434] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:30.990868 16700 heartbeater.cc:499] Master 127.15.190.62:40401 was elected leader, sending a full tablet report...
I20260812 06:17:30.990863 16718 raft_consensus.cc:697] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d [term 1 LEADER]: Becoming Leader. State: Replica: 51eea6fc722848c8a9b87f2a8af03a1d, State: Running, Role: LEADER
I20260812 06:17:30.991151 16718 consensus_queue.cc:237] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d [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: "51eea6fc722848c8a9b87f2a8af03a1d" member_type: VOTER last_known_addr { host: "127.15.190.1" port: 36213 } }
I20260812 06:17:30.992383 16478 catalog_manager.cc:5719] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d reported cstate change: term changed from 0 to 1, leader changed from <none> to 51eea6fc722848c8a9b87f2a8af03a1d (127.15.190.1). New cstate: current_term: 1 leader_uuid: "51eea6fc722848c8a9b87f2a8af03a1d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "51eea6fc722848c8a9b87f2a8af03a1d" member_type: VOTER last_known_addr { host: "127.15.190.1" port: 36213 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:31.043226 16120 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.048s	user 0.009s	sys 0.012s
I20260812 06:17:31.211227 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushMRSOp(ce1de6da81504daf921963209840fdf3): perf score=23.023690
I20260812 06:17:31.378527 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushMRSOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.167s	user 0.112s	sys 0.052s Metrics: {"bytes_written":13497197,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":48,"dirs.run_cpu_time_us":187,"dirs.run_wall_time_us":900,"drs_written":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42628,"lbm_writes_lt_1ms":886,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":5504,"update_count":1645}
I20260812 06:17:31.379287 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling LogGCOp(ce1de6da81504daf921963209840fdf3): free 20743880 bytes of WAL
I20260812 06:17:31.379570 16602 log_reader.cc:385] T ce1de6da81504daf921963209840fdf3: removed 2 log segments from log reader
I20260812 06:17:31.379632 16602 log.cc:1079] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/ce1de6da81504daf921963209840fdf3/wal-000000001 (ops 1-6)
I20260812 06:17:31.379663 16602 log.cc:1079] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/ce1de6da81504daf921963209840fdf3/wal-000000002 (ops 7-11)
I20260812 06:17:31.383935 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: LogGCOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.004s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:17:31.384272 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=2.188937
I20260812 06:17:31.399870 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.015s	user 0.009s	sys 0.003s Metrics: {"bytes_written":3323184,"delete_count":0,"lbm_write_time_us":4736,"lbm_writes_lt_1ms":84,"reinsert_count":0,"update_count":405}
I20260812 06:17:31.400259 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=2.188937
I20260812 06:17:31.408983 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3179,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:31.409319 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling UndoDeltaBlockGCOp(ce1de6da81504daf921963209840fdf3): 20513814 bytes on disk
I20260812 06:17:31.409651 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: UndoDeltaBlockGCOp(ce1de6da81504daf921963209840fdf3) 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:17:31.410006 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling MajorDeltaCompactionOp(ce1de6da81504daf921963209840fdf3): perf score=1.000000
I20260812 06:17:31.582880 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: MajorDeltaCompactionOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.173s	user 0.129s	sys 0.039s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815781,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":466,"lbm_read_time_us":10830,"lbm_reads_lt_1ms":569,"lbm_write_time_us":27958,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"thread_start_us":329,"threads_started":5,"update_count":2500}
I20260812 06:17:31.583412 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=14.095187
I20260812 06:17:31.632076 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.048s	user 0.033s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19413,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:31.632544 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=2.188937
I20260812 06:17:31.642416 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3697,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.642829 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling MajorDeltaCompactionOp(ce1de6da81504daf921963209840fdf3): perf score=1.000000
I20260812 06:17:31.827418 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: MajorDeltaCompactionOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.184s	user 0.129s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":971,"lbm_read_time_us":12185,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28369,"lbm_writes_lt_1ms":543,"mutex_wait_us":287,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":2500}
I20260812 06:17:31.828012 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=14.095187
I20260812 06:17:31.887056 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.059s	user 0.019s	sys 0.032s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19116,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:31.887652 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=2.188937
I20260812 06:17:31.902483 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5547,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.902980 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling MajorDeltaCompactionOp(ce1de6da81504daf921963209840fdf3): perf score=1.000000
I20260812 06:17:32.070916 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: MajorDeltaCompactionOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.168s	user 0.108s	sys 0.056s 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":591,"lbm_read_time_us":12153,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26648,"lbm_writes_lt_1ms":543,"mutex_wait_us":300,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:32.071367 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=11.118625
I20260812 06:17:32.099066 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.028s	user 0.008s	sys 0.016s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":11421,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:32.099661 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=2.188937
I20260812 06:17:32.125108 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.025s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4684,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:32.125576 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=2.188937
I20260812 06:17:32.135847 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3776,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.136284 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling MajorDeltaCompactionOp(ce1de6da81504daf921963209840fdf3): perf score=1.000000
I20260812 06:17:32.308017 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: MajorDeltaCompactionOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.171s	user 0.089s	sys 0.068s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":813,"lbm_read_time_us":10541,"lbm_reads_lt_1ms":573,"lbm_write_time_us":24929,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":2500}
I20260812 06:17:32.308523 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=14.095187
I20260812 06:17:32.354445 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.046s	user 0.022s	sys 0.016s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":17545,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:32.354984 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=2.188937
I20260812 06:17:32.370131 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5651,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.370731 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling MajorDeltaCompactionOp(ce1de6da81504daf921963209840fdf3): perf score=1.000000
I20260812 06:17:32.510807 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: MajorDeltaCompactionOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.140s	user 0.114s	sys 0.021s 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":280,"lbm_read_time_us":9029,"lbm_reads_lt_1ms":572,"lbm_write_time_us":24928,"lbm_writes_lt_1ms":543,"mutex_wait_us":48,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:32.511471 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=12.110812
I20260812 06:17:32.546710 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.035s	user 0.028s	sys 0.004s Metrics: {"bytes_written":13866410,"delete_count":0,"lbm_write_time_us":14929,"lbm_writes_lt_1ms":341,"reinsert_count":0,"update_count":1690}
I20260812 06:17:32.547299 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=1.196750
I20260812 06:17:32.566434 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.019s	user 0.007s	sys 0.000s Metrics: {"bytes_written":2543704,"delete_count":0,"lbm_write_time_us":3178,"lbm_writes_lt_1ms":65,"reinsert_count":0,"update_count":310}
I20260812 06:17:32.566982 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=2.188937
I20260812 06:17:32.577035 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3559,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.577693 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushMRSOp(ce1de6da81504daf921963209840fdf3): perf score=1.000000
I20260812 06:17:32.605149 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushMRSOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.027s	user 0.022s	sys 0.004s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":41,"dirs.run_cpu_time_us":169,"dirs.run_wall_time_us":1047,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1480,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:32.605762 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling LogGCOp(ce1de6da81504daf921963209840fdf3): free 124710235 bytes of WAL
I20260812 06:17:32.605991 16602 log_reader.cc:385] T ce1de6da81504daf921963209840fdf3: removed 12 log segments from log reader
I20260812 06:17:32.606051 16602 log.cc:1079] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/ce1de6da81504daf921963209840fdf3/wal-000000003 (ops 12-16)
I20260812 06:17:32.606096 16602 log.cc:1079] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/ce1de6da81504daf921963209840fdf3/wal-000000004 (ops 17-21)
I20260812 06:17:32.606130 16602 log.cc:1079] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/ce1de6da81504daf921963209840fdf3/wal-000000005 (ops 22-26)
I20260812 06:17:32.606160 16602 log.cc:1079] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/ce1de6da81504daf921963209840fdf3/wal-000000006 (ops 27-31)
I20260812 06:17:32.606189 16602 log.cc:1079] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/ce1de6da81504daf921963209840fdf3/wal-000000007 (ops 32-36)
I20260812 06:17:32.606216 16602 log.cc:1079] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/ce1de6da81504daf921963209840fdf3/wal-000000008 (ops 37-41)
I20260812 06:17:32.606245 16602 log.cc:1079] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/ce1de6da81504daf921963209840fdf3/wal-000000009 (ops 42-46)
I20260812 06:17:32.606276 16602 log.cc:1079] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/ce1de6da81504daf921963209840fdf3/wal-000000010 (ops 47-51)
I20260812 06:17:32.606307 16602 log.cc:1079] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/ce1de6da81504daf921963209840fdf3/wal-000000011 (ops 52-56)
I20260812 06:17:32.606335 16602 log.cc:1079] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/ce1de6da81504daf921963209840fdf3/wal-000000012 (ops 57-61)
I20260812 06:17:32.606361 16602 log.cc:1079] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/ce1de6da81504daf921963209840fdf3/wal-000000013 (ops 62-66)
I20260812 06:17:32.606388 16602 log.cc:1079] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/ce1de6da81504daf921963209840fdf3/wal-000000014 (ops 67-71)
I20260812 06:17:32.631171 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: LogGCOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.025s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:17:32.631573 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling UndoDeltaBlockGCOp(ce1de6da81504daf921963209840fdf3): 472 bytes on disk
I20260812 06:17:32.632048 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: UndoDeltaBlockGCOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:17:32.632488 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=3.181125
I20260812 06:17:32.654073 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.021s	user 0.005s	sys 0.013s Metrics: {"bytes_written":4512904,"delete_count":0,"lbm_write_time_us":4130,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:32.654608 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=2.188937
I20260812 06:17:32.668264 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.013s	user 0.007s	sys 0.006s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4949,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:32.668691 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling MajorDeltaCompactionOp(ce1de6da81504daf921963209840fdf3): perf score=1.000000
I20260812 06:17:32.900944 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: MajorDeltaCompactionOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.232s	user 0.162s	sys 0.068s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020821,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1229,"lbm_read_time_us":15174,"lbm_reads_lt_1ms":775,"lbm_write_time_us":36130,"lbm_writes_lt_1ms":743,"mutex_wait_us":234,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":6144,"thread_start_us":82,"threads_started":1,"update_count":3500}
I20260812 06:17:32.901484 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=15.087375
I20260812 06:17:32.941478 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.040s	user 0.027s	sys 0.012s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":17384,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:32.941910 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=2.188937
I20260812 06:17:32.963955 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.022s	user 0.009s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4521,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:32.964423 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=2.188937
I20260812 06:17:32.978858 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5307,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.979347 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling MajorDeltaCompactionOp(ce1de6da81504daf921963209840fdf3): perf score=1.000000
I20260812 06:17:33.169458 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: MajorDeltaCompactionOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.190s	user 0.119s	sys 0.071s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918202,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1146,"lbm_read_time_us":13386,"lbm_reads_lt_1ms":673,"lbm_write_time_us":29390,"lbm_writes_lt_1ms":643,"mutex_wait_us":308,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":3000}
I20260812 06:17:33.169999 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=14.095187
I20260812 06:17:33.224965 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.055s	user 0.030s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17563,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:33.225492 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=2.188937
I20260812 06:17:33.236246 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3786,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.236757 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling MajorDeltaCompactionOp(ce1de6da81504daf921963209840fdf3): perf score=1.000000
I20260812 06:17:33.400746 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: MajorDeltaCompactionOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.164s	user 0.109s	sys 0.049s 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":575,"lbm_read_time_us":11097,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26334,"lbm_writes_lt_1ms":543,"mutex_wait_us":291,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19968,"update_count":2500}
I20260812 06:17:33.401211 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=14.095187
I20260812 06:17:33.457494 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.056s	user 0.031s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20909,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:33.457988 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=2.188937
I20260812 06:17:33.467835 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3699,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.468236 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling MajorDeltaCompactionOp(ce1de6da81504daf921963209840fdf3): perf score=1.000000
I20260812 06:17:33.656881 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: MajorDeltaCompactionOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.188s	user 0.129s	sys 0.048s 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":481,"lbm_read_time_us":12894,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29539,"lbm_writes_lt_1ms":543,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":77440,"update_count":2500}
I20260812 06:17:33.657457 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=14.095187
I20260812 06:17:33.717015 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.059s	user 0.031s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18768,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:33.717552 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=2.188937
I20260812 06:17:33.727855 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3872,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.728272 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling MajorDeltaCompactionOp(ce1de6da81504daf921963209840fdf3): perf score=1.000000
I20260812 06:17:33.907437 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: MajorDeltaCompactionOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.179s	user 0.111s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":264,"lbm_read_time_us":12591,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26346,"lbm_writes_lt_1ms":543,"mutex_wait_us":60,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12800,"update_count":2500}
I20260812 06:17:33.908033 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=14.095187
I20260812 06:17:33.953890 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.046s	user 0.019s	sys 0.021s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17812,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:33.954468 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=2.188937
I20260812 06:17:33.973318 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.019s	user 0.010s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3754,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.974035 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushMRSOp(ce1de6da81504daf921963209840fdf3): perf score=1.000000
I20260812 06:17:34.006817 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushMRSOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.033s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":54,"dirs.run_cpu_time_us":188,"dirs.run_wall_time_us":1540,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1366,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:34.007464 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling LogGCOp(ce1de6da81504daf921963209840fdf3): free 112239372 bytes of WAL
I20260812 06:17:34.007676 16602 log_reader.cc:385] T ce1de6da81504daf921963209840fdf3: removed 11 log segments from log reader
I20260812 06:17:34.007725 16602 log.cc:1079] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/ce1de6da81504daf921963209840fdf3/wal-000000015 (ops 72-76)
I20260812 06:17:34.007752 16602 log.cc:1079] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/ce1de6da81504daf921963209840fdf3/wal-000000016 (ops 77-80)
I20260812 06:17:34.007781 16602 log.cc:1079] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/ce1de6da81504daf921963209840fdf3/wal-000000017 (ops 81-85)
I20260812 06:17:34.007835 16602 log.cc:1079] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/ce1de6da81504daf921963209840fdf3/wal-000000018 (ops 86-90)
I20260812 06:17:34.007869 16602 log.cc:1079] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/ce1de6da81504daf921963209840fdf3/wal-000000019 (ops 91-95)
I20260812 06:17:34.007900 16602 log.cc:1079] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/ce1de6da81504daf921963209840fdf3/wal-000000020 (ops 96-100)
I20260812 06:17:34.007930 16602 log.cc:1079] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/ce1de6da81504daf921963209840fdf3/wal-000000021 (ops 101-105)
I20260812 06:17:34.007961 16602 log.cc:1079] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/ce1de6da81504daf921963209840fdf3/wal-000000022 (ops 106-110)
I20260812 06:17:34.007992 16602 log.cc:1079] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/ce1de6da81504daf921963209840fdf3/wal-000000023 (ops 111-115)
I20260812 06:17:34.008023 16602 log.cc:1079] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/ce1de6da81504daf921963209840fdf3/wal-000000024 (ops 116-120)
I20260812 06:17:34.008054 16602 log.cc:1079] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/ce1de6da81504daf921963209840fdf3/wal-000000025 (ops 121-125)
I20260812 06:17:34.027282 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: LogGCOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.020s	user 0.000s	sys 0.016s Metrics: {}
I20260812 06:17:34.027663 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=3.181125
I20260812 06:17:34.048892 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.021s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4389831,"delete_count":0,"lbm_write_time_us":4225,"lbm_writes_lt_1ms":110,"reinsert_count":0,"update_count":535}
I20260812 06:17:34.049381 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=2.188937
I20260812 06:17:34.058869 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3815484,"delete_count":0,"lbm_write_time_us":3346,"lbm_writes_lt_1ms":96,"reinsert_count":0,"update_count":465}
I20260812 06:17:34.059492 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling MajorDeltaCompactionOp(ce1de6da81504daf921963209840fdf3): perf score=1.000000
I20260812 06:17:34.281015 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: MajorDeltaCompactionOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.221s	user 0.145s	sys 0.075s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020743,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":201,"lbm_read_time_us":14538,"lbm_reads_lt_1ms":774,"lbm_write_time_us":33752,"lbm_writes_lt_1ms":743,"mutex_wait_us":328,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":70272,"thread_start_us":89,"threads_started":1,"update_count":3500}
I20260812 06:17:34.281971 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=16.079562
I20260812 06:17:34.326267 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.044s	user 0.033s	sys 0.008s Metrics: {"bytes_written":18420085,"delete_count":0,"lbm_write_time_us":19530,"lbm_writes_lt_1ms":452,"reinsert_count":0,"update_count":2245}
I20260812 06:17:34.326830 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling UndoDeltaBlockGCOp(ce1de6da81504daf921963209840fdf3): 448 bytes on disk
I20260812 06:17:34.327324 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: UndoDeltaBlockGCOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4}
I20260812 06:17:34.327915 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=1.196750
I20260812 06:17:34.342659 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.015s	user 0.005s	sys 0.001s Metrics: {"bytes_written":2502683,"delete_count":0,"lbm_write_time_us":2404,"lbm_writes_lt_1ms":64,"reinsert_count":0,"update_count":305}
I20260812 06:17:34.343135 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=2.188937
I20260812 06:17:34.357023 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4911,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:34.357738 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling MajorDeltaCompactionOp(ce1de6da81504daf921963209840fdf3): perf score=1.000000
I20260812 06:17:34.568758 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: MajorDeltaCompactionOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.211s	user 0.150s	sys 0.060s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918168,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1054,"lbm_read_time_us":15745,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35044,"lbm_writes_lt_1ms":643,"mutex_wait_us":254,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9728,"update_count":3000}
I20260812 06:17:34.569455 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=14.095187
I20260812 06:17:34.617311 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.048s	user 0.023s	sys 0.020s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":19593,"lbm_writes_lt_1ms":413,"mutex_wait_us":3183,"reinsert_count":0,"update_count":2050}
I20260812 06:17:34.617930 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=2.188937
I20260812 06:17:34.634995 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.017s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4755,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:34.635502 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling MajorDeltaCompactionOp(ce1de6da81504daf921963209840fdf3): perf score=1.000000
I20260812 06:17:34.805505 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: MajorDeltaCompactionOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.170s	user 0.111s	sys 0.058s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815671,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":657,"lbm_read_time_us":12455,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29541,"lbm_writes_lt_1ms":543,"mutex_wait_us":428,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:34.806028 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=14.095187
I20260812 06:17:34.856536 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.050s	user 0.021s	sys 0.028s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22991,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:34.857160 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=2.188937
I20260812 06:17:34.873256 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.016s	user 0.008s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5078,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:34.873716 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling MajorDeltaCompactionOp(ce1de6da81504daf921963209840fdf3): perf score=1.000000
I20260812 06:17:35.037798 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: MajorDeltaCompactionOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.164s	user 0.123s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":191,"lbm_read_time_us":14553,"lbm_reads_lt_1ms":568,"lbm_write_time_us":25965,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2500}
I20260812 06:17:35.038486 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=14.095187
I20260812 06:17:35.095340 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.057s	user 0.024s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19615,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:35.095983 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=2.188937
I20260812 06:17:35.106056 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3798,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.106477 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling MajorDeltaCompactionOp(ce1de6da81504daf921963209840fdf3): perf score=1.000000
I20260812 06:17:35.271895 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: MajorDeltaCompactionOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.165s	user 0.101s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":308,"lbm_read_time_us":13073,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26100,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2500}
I20260812 06:17:35.272455 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=14.095187
I20260812 06:17:35.326225 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.054s	user 0.042s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23331,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:35.326800 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=2.188937
I20260812 06:17:35.346163 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.019s	user 0.010s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3980,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.346711 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushMRSOp(ce1de6da81504daf921963209840fdf3): perf score=1.000000
I20260812 06:17:35.380209 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushMRSOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.033s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":205,"dirs.run_wall_time_us":1508,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1330,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:35.380908 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling LogGCOp(ce1de6da81504daf921963209840fdf3): free 121006700 bytes of WAL
I20260812 06:17:35.381120 16602 log_reader.cc:385] T ce1de6da81504daf921963209840fdf3: removed 12 log segments from log reader
I20260812 06:17:35.381170 16602 log.cc:1079] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/ce1de6da81504daf921963209840fdf3/wal-000000026 (ops 126-130)
I20260812 06:17:35.381198 16602 log.cc:1079] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/ce1de6da81504daf921963209840fdf3/wal-000000027 (ops 131-135)
I20260812 06:17:35.381228 16602 log.cc:1079] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/ce1de6da81504daf921963209840fdf3/wal-000000028 (ops 136-140)
I20260812 06:17:35.381259 16602 log.cc:1079] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/ce1de6da81504daf921963209840fdf3/wal-000000029 (ops 141-145)
I20260812 06:17:35.381291 16602 log.cc:1079] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/ce1de6da81504daf921963209840fdf3/wal-000000030 (ops 146-150)
I20260812 06:17:35.381326 16602 log.cc:1079] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/ce1de6da81504daf921963209840fdf3/wal-000000031 (ops 151-155)
I20260812 06:17:35.381359 16602 log.cc:1079] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/ce1de6da81504daf921963209840fdf3/wal-000000032 (ops 156-160)
I20260812 06:17:35.381392 16602 log.cc:1079] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/ce1de6da81504daf921963209840fdf3/wal-000000033 (ops 161-165)
I20260812 06:17:35.381424 16602 log.cc:1079] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/ce1de6da81504daf921963209840fdf3/wal-000000034 (ops 166-170)
I20260812 06:17:35.381456 16602 log.cc:1079] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/ce1de6da81504daf921963209840fdf3/wal-000000035 (ops 171-174)
I20260812 06:17:35.381489 16602 log.cc:1079] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/ce1de6da81504daf921963209840fdf3/wal-000000036 (ops 175-179)
I20260812 06:17:35.381521 16602 log.cc:1079] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: Deleting log segment in path: /tmp/dist-test-taskD82ZjR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515446069121-16120-0/minicluster-data/ts-0-root/wals/ce1de6da81504daf921963209840fdf3/wal-000000037 (ops 180-184)
I20260812 06:17:35.401353 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: LogGCOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.020s	user 0.004s	sys 0.015s Metrics: {}
I20260812 06:17:35.402393 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=3.181125
I20260812 06:17:35.424780 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.022s	user 0.003s	sys 0.009s Metrics: {"bytes_written":4266759,"delete_count":0,"lbm_write_time_us":4914,"lbm_writes_lt_1ms":107,"reinsert_count":0,"update_count":520}
I20260812 06:17:35.425251 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling UndoDeltaBlockGCOp(ce1de6da81504daf921963209840fdf3): 447 bytes on disk
I20260812 06:17:35.425658 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: UndoDeltaBlockGCOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:17:35.426231 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=2.188937
I20260812 06:17:35.435484 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.009s	user 0.000s	sys 0.008s Metrics: {"bytes_written":3938559,"delete_count":0,"lbm_write_time_us":3458,"lbm_writes_lt_1ms":99,"reinsert_count":0,"update_count":480}
I20260812 06:17:35.435994 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling MajorDeltaCompactionOp(ce1de6da81504daf921963209840fdf3): perf score=1.000000
I20260812 06:17:35.668406 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: MajorDeltaCompactionOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.232s	user 0.149s	sys 0.077s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020745,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2772,"lbm_read_time_us":16444,"lbm_reads_lt_1ms":774,"lbm_write_time_us":35945,"lbm_writes_lt_1ms":743,"mutex_wait_us":1303,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2560,"thread_start_us":79,"threads_started":1,"update_count":3500}
I20260812 06:17:35.669005 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=18.063937
I20260812 06:17:35.730720 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.062s	user 0.029s	sys 0.016s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":21625,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:35.731205 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3): perf score=2.188937
I20260812 06:17:35.740844 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: FlushDeltaMemStoresOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3454,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.741238 16701 maintenance_manager.cc:419] P 51eea6fc722848c8a9b87f2a8af03a1d: Scheduling MajorDeltaCompactionOp(ce1de6da81504daf921963209840fdf3): perf score=1.000000
I20260812 06:17:35.771203 16120 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.728s	user 1.684s	sys 0.192s
I20260812 06:17:35.844504 16120 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.073s	user 0.003s	sys 0.000s
I20260812 06:17:35.845067 16120 tablet_server.cc:179] TabletServer@127.15.190.1:0 shutting down...
I20260812 06:17:35.902663 16602 maintenance_manager.cc:643] P 51eea6fc722848c8a9b87f2a8af03a1d: MajorDeltaCompactionOp(ce1de6da81504daf921963209840fdf3) complete. Timing: real 0.161s	user 0.117s	sys 0.043s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918099,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1359,"lbm_read_time_us":12972,"lbm_reads_lt_1ms":668,"lbm_write_time_us":28624,"lbm_writes_lt_1ms":643,"mutex_wait_us":550,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":18176,"update_count":3000}
I20260812 06:17:35.903230 16120 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:35.903417 16120 tablet_replica.cc:333] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d: stopping tablet replica
I20260812 06:17:35.903571 16120 raft_consensus.cc:2243] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:35.903740 16120 raft_consensus.cc:2272] T ce1de6da81504daf921963209840fdf3 P 51eea6fc722848c8a9b87f2a8af03a1d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:35.917759 16120 tablet_server.cc:196] TabletServer@127.15.190.1:0 shutdown complete.
I20260812 06:17:35.953719 16120 master.cc:562] Master@127.15.190.62:40401 shutting down...
I20260812 06:17:35.956588 16120 raft_consensus.cc:2243] T 00000000000000000000000000000000 P f797b795626441e88096b8210e236296 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:35.956772 16120 raft_consensus.cc:2272] T 00000000000000000000000000000000 P f797b795626441e88096b8210e236296 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:35.956847 16120 tablet_replica.cc:333] T 00000000000000000000000000000000 P f797b795626441e88096b8210e236296: stopping tablet replica
I20260812 06:17:35.968890 16120 master.cc:584] Master@127.15.190.62:40401 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5170 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (9962 ms total)

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