[==========] 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:18:28.310691 12282 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.11.254.190:33387
I20260812 06:18:28.311805 12282 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:18:28.312443 12282 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:28.319394 12297 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:18:28.319398 12282 server_base.cc:1061] running on GCE node
W20260812 06:18:28.319434 12299 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:18:28.319765 12292 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:18:28.320298 12282 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:28.320433 12282 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:18:28.320497 12282 hybrid_clock.cc:648] HybridClock initialized: now 1786515508320494 us; error 0 us; skew 500 ppm
I20260812 06:18:28.322461 12282 webserver.cc:533] Webserver started at http://127.11.254.190:35627/ using document root <none> and password file <none>
I20260812 06:18:28.323057 12282 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:28.323150 12282 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:28.323413 12282 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:28.325470 12282 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/master-0-root/instance:
uuid: "1a9fe149c8d249db8a2d22ffdff18b46"
format_stamp: "Formatted at 2026-08-12 06:18:28 on dist-test-slave-x5fp"
I20260812 06:18:28.329701 12282 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.004s	sys 0.000s
I20260812 06:18:28.332159 12307 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:18:28.333423 12282 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.001s
I20260812 06:18:28.333544 12282 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/master-0-root
uuid: "1a9fe149c8d249db8a2d22ffdff18b46"
format_stamp: "Formatted at 2026-08-12 06:18:28 on dist-test-slave-x5fp"
I20260812 06:18:28.333645 12282 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-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:18:28.351994 12282 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:28.352609 12282 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:18:28.352811 12282 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:28.360543 12282 rpc_server.cc:307] RPC server started. Bound to: 127.11.254.190:33387
I20260812 06:18:28.360555 12387 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.11.254.190:33387 every 8 connection(s)
I20260812 06:18:28.362882 12389 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:18:28.368232 12389 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1a9fe149c8d249db8a2d22ffdff18b46: Bootstrap starting.
I20260812 06:18:28.370645 12389 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 1a9fe149c8d249db8a2d22ffdff18b46: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:28.371559 12389 log.cc:826] T 00000000000000000000000000000000 P 1a9fe149c8d249db8a2d22ffdff18b46: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:28.373456 12389 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1a9fe149c8d249db8a2d22ffdff18b46: No bootstrap required, opened a new log
I20260812 06:18:28.376164 12389 raft_consensus.cc:359] T 00000000000000000000000000000000 P 1a9fe149c8d249db8a2d22ffdff18b46 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1a9fe149c8d249db8a2d22ffdff18b46" member_type: VOTER }
I20260812 06:18:28.376330 12389 raft_consensus.cc:385] T 00000000000000000000000000000000 P 1a9fe149c8d249db8a2d22ffdff18b46 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:28.376459 12389 raft_consensus.cc:740] T 00000000000000000000000000000000 P 1a9fe149c8d249db8a2d22ffdff18b46 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 1a9fe149c8d249db8a2d22ffdff18b46, State: Initialized, Role: FOLLOWER
I20260812 06:18:28.377072 12389 consensus_queue.cc:260] T 00000000000000000000000000000000 P 1a9fe149c8d249db8a2d22ffdff18b46 [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: "1a9fe149c8d249db8a2d22ffdff18b46" member_type: VOTER }
I20260812 06:18:28.377238 12389 raft_consensus.cc:399] T 00000000000000000000000000000000 P 1a9fe149c8d249db8a2d22ffdff18b46 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:28.377333 12389 raft_consensus.cc:493] T 00000000000000000000000000000000 P 1a9fe149c8d249db8a2d22ffdff18b46 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:28.377483 12389 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 1a9fe149c8d249db8a2d22ffdff18b46 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:28.378268 12389 raft_consensus.cc:515] T 00000000000000000000000000000000 P 1a9fe149c8d249db8a2d22ffdff18b46 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1a9fe149c8d249db8a2d22ffdff18b46" member_type: VOTER }
I20260812 06:18:28.378710 12389 leader_election.cc:304] T 00000000000000000000000000000000 P 1a9fe149c8d249db8a2d22ffdff18b46 [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: 1a9fe149c8d249db8a2d22ffdff18b46; no voters: 
I20260812 06:18:28.379031 12389 leader_election.cc:290] T 00000000000000000000000000000000 P 1a9fe149c8d249db8a2d22ffdff18b46 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:28.379204 12393 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 1a9fe149c8d249db8a2d22ffdff18b46 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:28.379477 12393 raft_consensus.cc:697] T 00000000000000000000000000000000 P 1a9fe149c8d249db8a2d22ffdff18b46 [term 1 LEADER]: Becoming Leader. State: Replica: 1a9fe149c8d249db8a2d22ffdff18b46, State: Running, Role: LEADER
I20260812 06:18:28.379844 12393 consensus_queue.cc:237] T 00000000000000000000000000000000 P 1a9fe149c8d249db8a2d22ffdff18b46 [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: "1a9fe149c8d249db8a2d22ffdff18b46" member_type: VOTER }
I20260812 06:18:28.380038 12389 sys_catalog.cc:565] T 00000000000000000000000000000000 P 1a9fe149c8d249db8a2d22ffdff18b46 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:28.381830 12396 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1a9fe149c8d249db8a2d22ffdff18b46 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 1a9fe149c8d249db8a2d22ffdff18b46. Latest consensus state: current_term: 1 leader_uuid: "1a9fe149c8d249db8a2d22ffdff18b46" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1a9fe149c8d249db8a2d22ffdff18b46" member_type: VOTER } }
I20260812 06:18:28.381875 12394 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1a9fe149c8d249db8a2d22ffdff18b46 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "1a9fe149c8d249db8a2d22ffdff18b46" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1a9fe149c8d249db8a2d22ffdff18b46" member_type: VOTER } }
I20260812 06:18:28.381974 12396 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1a9fe149c8d249db8a2d22ffdff18b46 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:28.381989 12394 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1a9fe149c8d249db8a2d22ffdff18b46 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:28.382383 12418 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:28.382509 12282 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:28.384889 12418 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:28.389446 12418 catalog_manager.cc:1383] Generated new cluster ID: 0ebc903156d24bdeb5a964805a7700b4
I20260812 06:18:28.389515 12418 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:28.427985 12418 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:28.429289 12418 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:28.436501 12418 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 1a9fe149c8d249db8a2d22ffdff18b46: Generated new TSK 0
I20260812 06:18:28.437289 12418 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:28.447625 12282 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:28.450721 12430 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:18:28.450831 12435 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:18:28.450870 12433 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:18:28.451061 12282 server_base.cc:1061] running on GCE node
I20260812 06:18:28.451233 12282 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:28.451280 12282 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:18:28.451297 12282 hybrid_clock.cc:648] HybridClock initialized: now 1786515508451297 us; error 0 us; skew 500 ppm
I20260812 06:18:28.452291 12282 webserver.cc:533] Webserver started at http://127.11.254.129:39845/ using document root <none> and password file <none>
I20260812 06:18:28.452500 12282 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:28.452569 12282 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:28.452654 12282 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:28.453085 12282 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root/instance:
uuid: "c5bec6942433440f984d043d8bd484f6"
format_stamp: "Formatted at 2026-08-12 06:18:28 on dist-test-slave-x5fp"
I20260812 06:18:28.454679 12282 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:28.455684 12443 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:18:28.455956 12282 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:28.456030 12282 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root
uuid: "c5bec6942433440f984d043d8bd484f6"
format_stamp: "Formatted at 2026-08-12 06:18:28 on dist-test-slave-x5fp"
I20260812 06:18:28.456123 12282 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-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:18:28.467147 12282 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:28.467576 12282 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:28.468082 12282 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:28.469074 12282 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:28.469131 12282 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:28.469201 12282 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:28.469244 12282 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:28.476393 12282 rpc_server.cc:307] RPC server started. Bound to: 127.11.254.129:44777
I20260812 06:18:28.476438 12556 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.11.254.129:44777 every 8 connection(s)
I20260812 06:18:28.491389 12557 heartbeater.cc:344] Connected to a master server at 127.11.254.190:33387
I20260812 06:18:28.491654 12557 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:28.492096 12557 heartbeater.cc:507] Master 127.11.254.190:33387 requested a full tablet report, sending...
I20260812 06:18:28.493508 12332 ts_manager.cc:194] Registered new tserver with Master: c5bec6942433440f984d043d8bd484f6 (127.11.254.129:44777)
I20260812 06:18:28.493788 12282 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01666123s
I20260812 06:18:28.494735 12332 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:50502
I20260812 06:18:28.502843 12332 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:50506:
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:18:28.517129 12495 tablet_service.cc:1511] Processing CreateTablet for tablet 5ed54867291c4ac68f5e0bee36ff1d76 (DEFAULT_TABLE table=heavy-update-compaction-test [id=f7c9cc8895984b789767812506bfd2d6]), partition=
I20260812 06:18:28.517582 12495 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 5ed54867291c4ac68f5e0bee36ff1d76. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:28.520478 12575 tablet_bootstrap.cc:492] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Bootstrap starting.
I20260812 06:18:28.521414 12575 tablet_bootstrap.cc:654] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:28.522521 12575 tablet_bootstrap.cc:492] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: No bootstrap required, opened a new log
I20260812 06:18:28.522648 12575 ts_tablet_manager.cc:1403] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:28.523110 12575 raft_consensus.cc:359] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c5bec6942433440f984d043d8bd484f6" member_type: VOTER last_known_addr { host: "127.11.254.129" port: 44777 } }
I20260812 06:18:28.523249 12575 raft_consensus.cc:385] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:28.523358 12575 raft_consensus.cc:740] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c5bec6942433440f984d043d8bd484f6, State: Initialized, Role: FOLLOWER
I20260812 06:18:28.523531 12575 consensus_queue.cc:260] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6 [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: "c5bec6942433440f984d043d8bd484f6" member_type: VOTER last_known_addr { host: "127.11.254.129" port: 44777 } }
I20260812 06:18:28.523685 12575 raft_consensus.cc:399] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:28.523744 12575 raft_consensus.cc:493] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:28.523789 12575 raft_consensus.cc:3060] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:28.524585 12575 raft_consensus.cc:515] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c5bec6942433440f984d043d8bd484f6" member_type: VOTER last_known_addr { host: "127.11.254.129" port: 44777 } }
I20260812 06:18:28.524703 12575 leader_election.cc:304] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6 [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: c5bec6942433440f984d043d8bd484f6; no voters: 
I20260812 06:18:28.524994 12575 leader_election.cc:290] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:28.525127 12577 raft_consensus.cc:2804] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:28.525362 12575 ts_tablet_manager.cc:1434] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Time spent starting tablet: real 0.003s	user 0.001s	sys 0.001s
I20260812 06:18:28.525413 12577 raft_consensus.cc:697] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6 [term 1 LEADER]: Becoming Leader. State: Replica: c5bec6942433440f984d043d8bd484f6, State: Running, Role: LEADER
I20260812 06:18:28.525568 12557 heartbeater.cc:499] Master 127.11.254.190:33387 was elected leader, sending a full tablet report...
I20260812 06:18:28.526043 12577 consensus_queue.cc:237] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6 [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: "c5bec6942433440f984d043d8bd484f6" member_type: VOTER last_known_addr { host: "127.11.254.129" port: 44777 } }
I20260812 06:18:28.528918 12332 catalog_manager.cc:5719] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6 reported cstate change: term changed from 0 to 1, leader changed from <none> to c5bec6942433440f984d043d8bd484f6 (127.11.254.129). New cstate: current_term: 1 leader_uuid: "c5bec6942433440f984d043d8bd484f6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c5bec6942433440f984d043d8bd484f6" member_type: VOTER last_known_addr { host: "127.11.254.129" port: 44777 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:28.592798 12282 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.023s	sys 0.004s
I20260812 06:18:28.727604 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushMRSOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=19.054940
I20260812 06:18:28.914410 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushMRSOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.186s	user 0.139s	sys 0.044s Metrics: {"bytes_written":13210025,"cfile_init":1,"compiler_manager_pool.queue_time_us":238,"delete_count":0,"dirs.queue_time_us":52,"dirs.run_cpu_time_us":182,"dirs.run_wall_time_us":861,"drs_written":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4,"lbm_write_time_us":45690,"lbm_writes_lt_1ms":779,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":768,"thread_start_us":166,"threads_started":1,"update_count":1610}
I20260812 06:18:28.915546 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling LogGCOp(5ed54867291c4ac68f5e0bee36ff1d76): free 20743880 bytes of WAL
I20260812 06:18:28.915910 12453 log_reader.cc:385] T 5ed54867291c4ac68f5e0bee36ff1d76: removed 2 log segments from log reader
I20260812 06:18:28.915988 12453 log.cc:1079] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5ed54867291c4ac68f5e0bee36ff1d76/wal-000000001 (ops 1-6)
I20260812 06:18:28.916041 12453 log.cc:1079] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5ed54867291c4ac68f5e0bee36ff1d76/wal-000000002 (ops 7-11)
I20260812 06:18:28.921682 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: LogGCOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.006s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:18:28.922048 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=4.173312
I20260812 06:18:28.948093 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.026s	user 0.008s	sys 0.015s Metrics: {"bytes_written":5948753,"delete_count":0,"lbm_write_time_us":8411,"lbm_writes_lt_1ms":148,"reinsert_count":0,"update_count":725}
I20260812 06:18:28.949249 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=1.000000
I20260812 06:18:28.957567 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.007s	user 0.006s	sys 0.000s Metrics: {"bytes_written":1353977,"delete_count":0,"lbm_write_time_us":2139,"lbm_writes_lt_1ms":36,"reinsert_count":0,"update_count":165}
I20260812 06:18:28.961807 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling UndoDeltaBlockGCOp(5ed54867291c4ac68f5e0bee36ff1d76): 16411394 bytes on disk
I20260812 06:18:28.962522 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: UndoDeltaBlockGCOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:18:28.963006 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling MajorDeltaCompactionOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=1.000000
I20260812 06:18:29.141852 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: MajorDeltaCompactionOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.179s	user 0.127s	sys 0.051s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774750,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":531,"lbm_read_time_us":12074,"lbm_reads_lt_1ms":561,"lbm_write_time_us":32163,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9088,"thread_start_us":314,"threads_started":5,"update_count":2500}
I20260812 06:18:29.142436 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=10.126437
I20260812 06:18:29.180958 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.038s	user 0.015s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16762,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:29.181546 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=2.188937
I20260812 06:18:29.202472 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.021s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5773,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.202922 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling MajorDeltaCompactionOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=1.000000
I20260812 06:18:29.331697 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: MajorDeltaCompactionOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.129s	user 0.094s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":268,"lbm_read_time_us":8722,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24270,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":72064,"update_count":2000}
I20260812 06:18:29.332494 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=10.126437
I20260812 06:18:29.368752 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.036s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14684,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:29.369367 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=2.188937
I20260812 06:18:29.384971 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5101,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.385478 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling MajorDeltaCompactionOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=1.000000
I20260812 06:18:29.513290 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: MajorDeltaCompactionOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.128s	user 0.108s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":197,"lbm_read_time_us":9777,"lbm_reads_lt_1ms":468,"lbm_write_time_us":24919,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16384,"update_count":2000}
I20260812 06:18:29.516548 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=11.118625
I20260812 06:18:29.561053 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.044s	user 0.029s	sys 0.015s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":19384,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:29.561653 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=2.188937
I20260812 06:18:29.577018 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5646,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:29.577534 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling MajorDeltaCompactionOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=1.000000
I20260812 06:18:29.718537 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: MajorDeltaCompactionOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.141s	user 0.108s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672267,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":227,"lbm_read_time_us":10759,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27851,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":2000}
I20260812 06:18:29.719247 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=10.126437
I20260812 06:18:29.763929 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.045s	user 0.014s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18130,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:29.764545 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=2.188937
I20260812 06:18:29.775051 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4032,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.775552 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling MajorDeltaCompactionOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=1.000000
I20260812 06:18:29.925319 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: MajorDeltaCompactionOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.150s	user 0.113s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":258,"lbm_read_time_us":11183,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24378,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2000}
I20260812 06:18:29.925930 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=10.126437
I20260812 06:18:29.974598 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.049s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16161,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:29.975085 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=2.188937
I20260812 06:18:29.989681 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.014s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5607,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.990236 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling MajorDeltaCompactionOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=1.000000
I20260812 06:18:30.116931 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: MajorDeltaCompactionOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.126s	user 0.092s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":3776,"lbm_read_time_us":9243,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25305,"lbm_writes_lt_1ms":443,"mutex_wait_us":2828,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":2000}
I20260812 06:18:30.118395 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=10.126437
I20260812 06:18:30.157243 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.039s	user 0.030s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15019,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:30.157761 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=2.188937
I20260812 06:18:30.168951 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.011s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4038,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.169435 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushMRSOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=1.000000
I20260812 06:18:30.196120 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushMRSOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.027s	user 0.023s	sys 0.001s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":265,"dirs.run_wall_time_us":1551,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1356,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:30.197021 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling LogGCOp(5ed54867291c4ac68f5e0bee36ff1d76): free 112239277 bytes of WAL
I20260812 06:18:30.197281 12453 log_reader.cc:385] T 5ed54867291c4ac68f5e0bee36ff1d76: removed 11 log segments from log reader
I20260812 06:18:30.197345 12453 log.cc:1079] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5ed54867291c4ac68f5e0bee36ff1d76/wal-000000003 (ops 12-16)
I20260812 06:18:30.197384 12453 log.cc:1079] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5ed54867291c4ac68f5e0bee36ff1d76/wal-000000004 (ops 17-21)
I20260812 06:18:30.197419 12453 log.cc:1079] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5ed54867291c4ac68f5e0bee36ff1d76/wal-000000005 (ops 22-26)
I20260812 06:18:30.197446 12453 log.cc:1079] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5ed54867291c4ac68f5e0bee36ff1d76/wal-000000006 (ops 27-30)
I20260812 06:18:30.197480 12453 log.cc:1079] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5ed54867291c4ac68f5e0bee36ff1d76/wal-000000007 (ops 31-35)
I20260812 06:18:30.197510 12453 log.cc:1079] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5ed54867291c4ac68f5e0bee36ff1d76/wal-000000008 (ops 36-40)
I20260812 06:18:30.197539 12453 log.cc:1079] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5ed54867291c4ac68f5e0bee36ff1d76/wal-000000009 (ops 41-45)
I20260812 06:18:30.197569 12453 log.cc:1079] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5ed54867291c4ac68f5e0bee36ff1d76/wal-000000010 (ops 46-50)
I20260812 06:18:30.197602 12453 log.cc:1079] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5ed54867291c4ac68f5e0bee36ff1d76/wal-000000011 (ops 51-55)
I20260812 06:18:30.197636 12453 log.cc:1079] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5ed54867291c4ac68f5e0bee36ff1d76/wal-000000012 (ops 56-60)
I20260812 06:18:30.197665 12453 log.cc:1079] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5ed54867291c4ac68f5e0bee36ff1d76/wal-000000013 (ops 61-65)
I20260812 06:18:30.225579 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: LogGCOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.028s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:18:30.226024 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=2.188937
I20260812 06:18:30.248798 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.023s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4945,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.249239 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling LogGCOp(5ed54867291c4ac68f5e0bee36ff1d76): free 12017983 bytes of WAL
I20260812 06:18:30.249457 12453 log_reader.cc:385] T 5ed54867291c4ac68f5e0bee36ff1d76: removed 1 log segments from log reader
I20260812 06:18:30.249517 12453 log.cc:1079] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5ed54867291c4ac68f5e0bee36ff1d76/wal-000000014 (ops 66-70)
I20260812 06:18:30.251874 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: LogGCOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:30.252153 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling UndoDeltaBlockGCOp(5ed54867291c4ac68f5e0bee36ff1d76): 461 bytes on disk
I20260812 06:18:30.252556 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: UndoDeltaBlockGCOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:18:30.253013 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=2.188937
I20260812 06:18:30.265391 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4207,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.265836 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling MajorDeltaCompactionOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=1.000000
I20260812 06:18:30.446278 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: MajorDeltaCompactionOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.180s	user 0.130s	sys 0.048s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877338,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":662,"lbm_read_time_us":12363,"lbm_reads_lt_1ms":666,"lbm_write_time_us":33725,"lbm_writes_lt_1ms":643,"mutex_wait_us":43,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8448,"thread_start_us":106,"threads_started":1,"update_count":3000}
I20260812 06:18:30.446949 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=14.095187
I20260812 06:18:30.508930 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.062s	user 0.033s	sys 0.028s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":29022,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:30.509536 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=2.188937
I20260812 06:18:30.523957 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.014s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4912,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.524464 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling MajorDeltaCompactionOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=1.000000
I20260812 06:18:30.685423 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: MajorDeltaCompactionOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.161s	user 0.126s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":263,"lbm_read_time_us":11170,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30560,"lbm_writes_lt_1ms":543,"mutex_wait_us":70,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:18:30.686220 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=14.095187
I20260812 06:18:30.749392 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.063s	user 0.035s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21893,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:30.750012 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=2.188937
I20260812 06:18:30.760340 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3937,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.761018 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling MajorDeltaCompactionOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=1.000000
I20260812 06:18:30.941398 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: MajorDeltaCompactionOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.180s	user 0.124s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":322,"lbm_read_time_us":12450,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33350,"lbm_writes_lt_1ms":543,"mutex_wait_us":42,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5504,"update_count":2500}
I20260812 06:18:30.941859 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=14.095187
I20260812 06:18:31.001016 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.059s	user 0.032s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20677,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:31.001564 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=2.188937
I20260812 06:18:31.013379 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4204,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.014238 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling MajorDeltaCompactionOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=1.000000
I20260812 06:18:31.201682 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: MajorDeltaCompactionOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.187s	user 0.135s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":834,"lbm_read_time_us":12204,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31588,"lbm_writes_lt_1ms":543,"mutex_wait_us":373,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2500}
I20260812 06:18:31.202225 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=14.095187
I20260812 06:18:31.265179 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.063s	user 0.033s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20991,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:31.265731 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=2.188937
I20260812 06:18:31.276405 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4214,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.276983 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling MajorDeltaCompactionOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=1.000000
I20260812 06:18:31.446599 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: MajorDeltaCompactionOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.169s	user 0.116s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":360,"lbm_read_time_us":12299,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32339,"lbm_writes_lt_1ms":543,"mutex_wait_us":54,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:31.447400 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=10.126437
I20260812 06:18:31.490640 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.043s	user 0.026s	sys 0.015s Metrics: {"bytes_written":12307495,"delete_count":0,"lbm_write_time_us":18443,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:31.491587 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=2.188937
I20260812 06:18:31.525621 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.034s	user 0.014s	sys 0.011s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6965,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.526154 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=2.188937
I20260812 06:18:31.537099 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4232,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.537624 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling MajorDeltaCompactionOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=1.000000
I20260812 06:18:31.708986 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: MajorDeltaCompactionOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.171s	user 0.134s	sys 0.036s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774812,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1339,"lbm_read_time_us":13505,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28417,"lbm_writes_lt_1ms":543,"mutex_wait_us":341,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2500}
I20260812 06:18:31.709587 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=10.126437
I20260812 06:18:31.744660 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.035s	user 0.016s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14993,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:31.745831 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=2.188937
I20260812 06:18:31.762109 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.016s	user 0.002s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6508,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.762657 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushMRSOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=1.000000
I20260812 06:18:31.789340 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushMRSOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.027s	user 0.022s	sys 0.004s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":191,"dirs.run_wall_time_us":1320,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1655,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:31.790045 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling LogGCOp(5ed54867291c4ac68f5e0bee36ff1d76): free 121006436 bytes of WAL
I20260812 06:18:31.790277 12453 log_reader.cc:385] T 5ed54867291c4ac68f5e0bee36ff1d76: removed 12 log segments from log reader
I20260812 06:18:31.790339 12453 log.cc:1079] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5ed54867291c4ac68f5e0bee36ff1d76/wal-000000015 (ops 71-75)
I20260812 06:18:31.790395 12453 log.cc:1079] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5ed54867291c4ac68f5e0bee36ff1d76/wal-000000016 (ops 76-80)
I20260812 06:18:31.790453 12453 log.cc:1079] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5ed54867291c4ac68f5e0bee36ff1d76/wal-000000017 (ops 81-84)
I20260812 06:18:31.790498 12453 log.cc:1079] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5ed54867291c4ac68f5e0bee36ff1d76/wal-000000018 (ops 85-89)
I20260812 06:18:31.790535 12453 log.cc:1079] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5ed54867291c4ac68f5e0bee36ff1d76/wal-000000019 (ops 90-94)
I20260812 06:18:31.790575 12453 log.cc:1079] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5ed54867291c4ac68f5e0bee36ff1d76/wal-000000020 (ops 95-99)
I20260812 06:18:31.790616 12453 log.cc:1079] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5ed54867291c4ac68f5e0bee36ff1d76/wal-000000021 (ops 100-104)
I20260812 06:18:31.790654 12453 log.cc:1079] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5ed54867291c4ac68f5e0bee36ff1d76/wal-000000022 (ops 105-109)
I20260812 06:18:31.790694 12453 log.cc:1079] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5ed54867291c4ac68f5e0bee36ff1d76/wal-000000023 (ops 110-114)
I20260812 06:18:31.790733 12453 log.cc:1079] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5ed54867291c4ac68f5e0bee36ff1d76/wal-000000024 (ops 115-119)
I20260812 06:18:31.790776 12453 log.cc:1079] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5ed54867291c4ac68f5e0bee36ff1d76/wal-000000025 (ops 120-124)
I20260812 06:18:31.790815 12453 log.cc:1079] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5ed54867291c4ac68f5e0bee36ff1d76/wal-000000026 (ops 125-129)
I20260812 06:18:31.818856 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: LogGCOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.029s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:18:31.819289 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling UndoDeltaBlockGCOp(5ed54867291c4ac68f5e0bee36ff1d76): 483 bytes on disk
I20260812 06:18:31.819855 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: UndoDeltaBlockGCOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:18:31.820340 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=5.165500
I20260812 06:18:31.841243 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.021s	user 0.013s	sys 0.008s Metrics: {"bytes_written":7302546,"delete_count":0,"lbm_write_time_us":8840,"lbm_writes_lt_1ms":181,"mutex_wait_us":115,"reinsert_count":0,"update_count":890}
I20260812 06:18:31.841718 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling MajorDeltaCompactionOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=1.000000
I20260812 06:18:32.038173 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: MajorDeltaCompactionOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.196s	user 0.112s	sys 0.078s Metrics: {"cfile_cache_miss":611,"cfile_cache_miss_bytes":27974689,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":210,"lbm_read_time_us":13835,"lbm_reads_lt_1ms":647,"lbm_write_time_us":34408,"lbm_writes_lt_1ms":621,"mutex_wait_us":37,"peak_mem_usage":72558934,"reinsert_count":0,"spinlock_wait_cycles":3968,"thread_start_us":76,"threads_started":1,"update_count":2890}
I20260812 06:18:32.039012 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=15.087375
I20260812 06:18:32.101207 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.062s	user 0.036s	sys 0.021s Metrics: {"bytes_written":17312440,"delete_count":0,"lbm_write_time_us":22294,"lbm_writes_lt_1ms":425,"reinsert_count":0,"update_count":2110}
I20260812 06:18:32.101778 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=2.188937
I20260812 06:18:32.112447 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4241,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.112908 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling MajorDeltaCompactionOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=1.000000
I20260812 06:18:32.294833 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: MajorDeltaCompactionOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.182s	user 0.117s	sys 0.057s Metrics: {"cfile_cache_miss":554,"cfile_cache_miss_bytes":25677227,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":268,"lbm_read_time_us":14108,"lbm_reads_lt_1ms":594,"lbm_write_time_us":31755,"lbm_writes_lt_1ms":565,"mutex_wait_us":22,"peak_mem_usage":65059054,"reinsert_count":0,"spinlock_wait_cycles":10752,"update_count":2610}
I20260812 06:18:32.295557 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=14.095187
I20260812 06:18:32.357651 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.062s	user 0.026s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19426,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:32.358320 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=2.188937
I20260812 06:18:32.370558 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4793,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.371116 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling MajorDeltaCompactionOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=1.000000
I20260812 06:18:32.551085 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: MajorDeltaCompactionOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.180s	user 0.124s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":621,"lbm_read_time_us":15098,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29882,"lbm_writes_lt_1ms":543,"mutex_wait_us":134,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2500}
I20260812 06:18:32.551774 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=11.118625
I20260812 06:18:32.590714 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.039s	user 0.022s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15171,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:18:32.591259 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=2.188937
I20260812 06:18:32.612883 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.021s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5293,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:32.613413 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=2.188937
I20260812 06:18:32.627676 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.014s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5854,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.628311 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling MajorDeltaCompactionOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=1.000000
I20260812 06:18:32.795485 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: MajorDeltaCompactionOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.167s	user 0.111s	sys 0.056s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":603,"lbm_read_time_us":13261,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27500,"lbm_writes_lt_1ms":543,"mutex_wait_us":102,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2500}
I20260812 06:18:32.796211 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=11.118625
I20260812 06:18:32.831837 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.035s	user 0.017s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14735,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:32.832484 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=2.188937
I20260812 06:18:32.854869 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.022s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5142,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:32.855330 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=2.188937
I20260812 06:18:32.865857 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4129,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.866315 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling MajorDeltaCompactionOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=1.000000
I20260812 06:18:33.022449 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: MajorDeltaCompactionOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.156s	user 0.099s	sys 0.053s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":881,"lbm_read_time_us":10020,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29366,"lbm_writes_lt_1ms":543,"mutex_wait_us":277,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":2500}
I20260812 06:18:33.023252 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=11.118625
I20260812 06:18:33.071617 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.048s	user 0.016s	sys 0.029s Metrics: {"bytes_written":12717742,"delete_count":0,"lbm_write_time_us":21786,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:18:33.072130 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=2.188937
I20260812 06:18:33.091090 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.019s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4828,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.091583 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=2.188937
I20260812 06:18:33.101835 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3754,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:33.102427 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling MajorDeltaCompactionOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=1.000000
I20260812 06:18:33.256155 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: MajorDeltaCompactionOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.153s	user 0.131s	sys 0.020s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774806,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":653,"lbm_read_time_us":9311,"lbm_reads_lt_1ms":573,"lbm_write_time_us":33879,"lbm_writes_lt_1ms":543,"mutex_wait_us":292,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:33.256764 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=11.118625
I20260812 06:18:33.287606 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.031s	user 0.026s	sys 0.002s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":13257,"lbm_writes_lt_1ms":313,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":1550}
I20260812 06:18:33.288473 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=2.188937
I20260812 06:18:33.315307 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.027s	user 0.003s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":7558,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":450}
I20260812 06:18:33.315817 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=2.188937
I20260812 06:18:33.326392 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3933,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.326890 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushMRSOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=1.000000
I20260812 06:18:33.362107 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushMRSOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.035s	user 0.032s	sys 0.002s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":223,"dirs.run_wall_time_us":1731,"drs_written":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2149,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:33.362972 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling LogGCOp(5ed54867291c4ac68f5e0bee36ff1d76): free 132571598 bytes of WAL
I20260812 06:18:33.363265 12453 log_reader.cc:385] T 5ed54867291c4ac68f5e0bee36ff1d76: removed 13 log segments from log reader
I20260812 06:18:33.363335 12453 log.cc:1079] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5ed54867291c4ac68f5e0bee36ff1d76/wal-000000027 (ops 130-134)
I20260812 06:18:33.363382 12453 log.cc:1079] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5ed54867291c4ac68f5e0bee36ff1d76/wal-000000028 (ops 135-139)
I20260812 06:18:33.363420 12453 log.cc:1079] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5ed54867291c4ac68f5e0bee36ff1d76/wal-000000029 (ops 140-144)
I20260812 06:18:33.363451 12453 log.cc:1079] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5ed54867291c4ac68f5e0bee36ff1d76/wal-000000030 (ops 145-149)
I20260812 06:18:33.363478 12453 log.cc:1079] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5ed54867291c4ac68f5e0bee36ff1d76/wal-000000031 (ops 150-154)
I20260812 06:18:33.363512 12453 log.cc:1079] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5ed54867291c4ac68f5e0bee36ff1d76/wal-000000032 (ops 155-158)
I20260812 06:18:33.363544 12453 log.cc:1079] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5ed54867291c4ac68f5e0bee36ff1d76/wal-000000033 (ops 159-163)
I20260812 06:18:33.363574 12453 log.cc:1079] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5ed54867291c4ac68f5e0bee36ff1d76/wal-000000034 (ops 164-168)
I20260812 06:18:33.363598 12453 log.cc:1079] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5ed54867291c4ac68f5e0bee36ff1d76/wal-000000035 (ops 169-173)
I20260812 06:18:33.363628 12453 log.cc:1079] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5ed54867291c4ac68f5e0bee36ff1d76/wal-000000036 (ops 174-178)
I20260812 06:18:33.363651 12453 log.cc:1079] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5ed54867291c4ac68f5e0bee36ff1d76/wal-000000037 (ops 179-183)
I20260812 06:18:33.363682 12453 log.cc:1079] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5ed54867291c4ac68f5e0bee36ff1d76/wal-000000038 (ops 184-188)
I20260812 06:18:33.363713 12453 log.cc:1079] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5ed54867291c4ac68f5e0bee36ff1d76/wal-000000039 (ops 189-192)
I20260812 06:18:33.393002 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: LogGCOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.030s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:18:33.393522 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling UndoDeltaBlockGCOp(5ed54867291c4ac68f5e0bee36ff1d76): 492 bytes on disk
I20260812 06:18:33.393988 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: UndoDeltaBlockGCOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:18:33.394549 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=3.181125
I20260812 06:18:33.409937 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.015s	user 0.004s	sys 0.010s Metrics: {"bytes_written":5046217,"delete_count":0,"lbm_write_time_us":6069,"lbm_writes_lt_1ms":126,"reinsert_count":0,"update_count":615}
I20260812 06:18:33.410542 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=1.196750
I20260812 06:18:33.423537 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: FlushDeltaMemStoresOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3159080,"delete_count":0,"lbm_write_time_us":4613,"lbm_writes_lt_1ms":80,"reinsert_count":0,"update_count":385}
I20260812 06:18:33.424281 12558 maintenance_manager.cc:419] P c5bec6942433440f984d043d8bd484f6: Scheduling MajorDeltaCompactionOp(5ed54867291c4ac68f5e0bee36ff1d76): perf score=1.000000
I20260812 06:18:33.537746 12282 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.945s	user 1.820s	sys 0.145s
I20260812 06:18:33.649266 12282 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.111s	user 0.003s	sys 0.000s
I20260812 06:18:33.649900 12282 tablet_server.cc:179] TabletServer@127.11.254.129:0 shutting down...
I20260812 06:18:33.657004 12453 maintenance_manager.cc:643] P c5bec6942433440f984d043d8bd484f6: MajorDeltaCompactionOp(5ed54867291c4ac68f5e0bee36ff1d76) complete. Timing: real 0.232s	user 0.148s	sys 0.076s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979841,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":435,"lbm_read_time_us":16441,"lbm_reads_lt_1ms":771,"lbm_write_time_us":40712,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":742,"mutex_wait_us":65,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":120,"threads_started":1,"update_count":3500}
I20260812 06:18:33.657620 12282 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:33.658159 12282 tablet_replica.cc:333] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6: stopping tablet replica
I20260812 06:18:33.658411 12282 raft_consensus.cc:2243] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:33.658686 12282 raft_consensus.cc:2272] T 5ed54867291c4ac68f5e0bee36ff1d76 P c5bec6942433440f984d043d8bd484f6 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:33.675722 12282 tablet_server.cc:196] TabletServer@127.11.254.129:0 shutdown complete.
I20260812 06:18:33.712321 12282 master.cc:562] Master@127.11.254.190:33387 shutting down...
I20260812 06:18:33.715960 12282 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 1a9fe149c8d249db8a2d22ffdff18b46 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:33.716131 12282 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 1a9fe149c8d249db8a2d22ffdff18b46 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:33.716187 12282 tablet_replica.cc:333] T 00000000000000000000000000000000 P 1a9fe149c8d249db8a2d22ffdff18b46: stopping tablet replica
I20260812 06:18:33.728631 12282 master.cc:584] Master@127.11.254.190:33387 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5507 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:33.832008 12282 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.11.254.190:40727
I20260812 06:18:33.832490 12282 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:33.834621 12609 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:18:33.834759 12282 server_base.cc:1061] running on GCE node
W20260812 06:18:33.834630 12607 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:18:33.834899 12611 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:18:33.835106 12282 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:33.835155 12282 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:18:33.835170 12282 hybrid_clock.cc:648] HybridClock initialized: now 1786515513835169 us; error 0 us; skew 500 ppm
I20260812 06:18:33.836063 12282 webserver.cc:533] Webserver started at http://127.11.254.190:38703/ using document root <none> and password file <none>
I20260812 06:18:33.836257 12282 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:33.836328 12282 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:33.836423 12282 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:33.836913 12282 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/master-0-root/instance:
uuid: "a2754903350b477d85813f80f2e8843b"
format_stamp: "Formatted at 2026-08-12 06:18:33 on dist-test-slave-x5fp"
I20260812 06:18:33.838457 12282 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:33.839349 12617 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:18:33.839723 12282 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:33.839818 12282 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/master-0-root
uuid: "a2754903350b477d85813f80f2e8843b"
format_stamp: "Formatted at 2026-08-12 06:18:33 on dist-test-slave-x5fp"
I20260812 06:18:33.839907 12282 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-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:18:33.859756 12282 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:33.860209 12282 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:33.869801 12282 rpc_server.cc:307] RPC server started. Bound to: 127.11.254.190:40727
I20260812 06:18:33.872777 12691 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.11.254.190:40727 every 8 connection(s)
I20260812 06:18:33.873974 12692 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:18:33.876372 12692 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a2754903350b477d85813f80f2e8843b: Bootstrap starting.
I20260812 06:18:33.877266 12692 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P a2754903350b477d85813f80f2e8843b: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:33.878466 12692 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a2754903350b477d85813f80f2e8843b: No bootstrap required, opened a new log
I20260812 06:18:33.878916 12692 raft_consensus.cc:359] T 00000000000000000000000000000000 P a2754903350b477d85813f80f2e8843b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a2754903350b477d85813f80f2e8843b" member_type: VOTER }
I20260812 06:18:33.879006 12692 raft_consensus.cc:385] T 00000000000000000000000000000000 P a2754903350b477d85813f80f2e8843b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:33.879029 12692 raft_consensus.cc:740] T 00000000000000000000000000000000 P a2754903350b477d85813f80f2e8843b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a2754903350b477d85813f80f2e8843b, State: Initialized, Role: FOLLOWER
I20260812 06:18:33.879230 12692 consensus_queue.cc:260] T 00000000000000000000000000000000 P a2754903350b477d85813f80f2e8843b [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: "a2754903350b477d85813f80f2e8843b" member_type: VOTER }
I20260812 06:18:33.879307 12692 raft_consensus.cc:399] T 00000000000000000000000000000000 P a2754903350b477d85813f80f2e8843b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:33.879370 12692 raft_consensus.cc:493] T 00000000000000000000000000000000 P a2754903350b477d85813f80f2e8843b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:33.879434 12692 raft_consensus.cc:3060] T 00000000000000000000000000000000 P a2754903350b477d85813f80f2e8843b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:33.880165 12692 raft_consensus.cc:515] T 00000000000000000000000000000000 P a2754903350b477d85813f80f2e8843b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a2754903350b477d85813f80f2e8843b" member_type: VOTER }
I20260812 06:18:33.880318 12692 leader_election.cc:304] T 00000000000000000000000000000000 P a2754903350b477d85813f80f2e8843b [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: a2754903350b477d85813f80f2e8843b; no voters: 
I20260812 06:18:33.880529 12692 leader_election.cc:290] T 00000000000000000000000000000000 P a2754903350b477d85813f80f2e8843b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:33.880697 12695 raft_consensus.cc:2804] T 00000000000000000000000000000000 P a2754903350b477d85813f80f2e8843b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:33.880967 12695 raft_consensus.cc:697] T 00000000000000000000000000000000 P a2754903350b477d85813f80f2e8843b [term 1 LEADER]: Becoming Leader. State: Replica: a2754903350b477d85813f80f2e8843b, State: Running, Role: LEADER
I20260812 06:18:33.881018 12692 sys_catalog.cc:565] T 00000000000000000000000000000000 P a2754903350b477d85813f80f2e8843b [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:33.881106 12695 consensus_queue.cc:237] T 00000000000000000000000000000000 P a2754903350b477d85813f80f2e8843b [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: "a2754903350b477d85813f80f2e8843b" member_type: VOTER }
I20260812 06:18:33.881598 12696 sys_catalog.cc:455] T 00000000000000000000000000000000 P a2754903350b477d85813f80f2e8843b [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "a2754903350b477d85813f80f2e8843b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a2754903350b477d85813f80f2e8843b" member_type: VOTER } }
I20260812 06:18:33.881649 12697 sys_catalog.cc:455] T 00000000000000000000000000000000 P a2754903350b477d85813f80f2e8843b [sys.catalog]: SysCatalogTable state changed. Reason: New leader a2754903350b477d85813f80f2e8843b. Latest consensus state: current_term: 1 leader_uuid: "a2754903350b477d85813f80f2e8843b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a2754903350b477d85813f80f2e8843b" member_type: VOTER } }
I20260812 06:18:33.881753 12697 sys_catalog.cc:458] T 00000000000000000000000000000000 P a2754903350b477d85813f80f2e8843b [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:33.881697 12696 sys_catalog.cc:458] T 00000000000000000000000000000000 P a2754903350b477d85813f80f2e8843b [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:33.882051 12706 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:33.883038 12706 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:33.883219 12282 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:33.884956 12706 catalog_manager.cc:1383] Generated new cluster ID: 126790b076a44d198354d5a21080f593
I20260812 06:18:33.885015 12706 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:33.894410 12706 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:33.895013 12706 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:33.903383 12706 catalog_manager.cc:6092] T 00000000000000000000000000000000 P a2754903350b477d85813f80f2e8843b: Generated new TSK 0
I20260812 06:18:33.903568 12706 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:33.915704 12282 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:33.918037 12728 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:18:33.918157 12732 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:18:33.918305 12282 server_base.cc:1061] running on GCE node
W20260812 06:18:33.918141 12727 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:18:33.918577 12282 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:33.918625 12282 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:18:33.918644 12282 hybrid_clock.cc:648] HybridClock initialized: now 1786515513918644 us; error 0 us; skew 500 ppm
I20260812 06:18:33.919615 12282 webserver.cc:533] Webserver started at http://127.11.254.129:39543/ using document root <none> and password file <none>
I20260812 06:18:33.919828 12282 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:33.919909 12282 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:33.920032 12282 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:33.920465 12282 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root/instance:
uuid: "bce5ced4082e4ea4a3b59684ba9eb740"
format_stamp: "Formatted at 2026-08-12 06:18:33 on dist-test-slave-x5fp"
I20260812 06:18:33.922224 12282 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:33.923276 12738 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:18:33.923647 12282 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:33.923744 12282 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root
uuid: "bce5ced4082e4ea4a3b59684ba9eb740"
format_stamp: "Formatted at 2026-08-12 06:18:33 on dist-test-slave-x5fp"
I20260812 06:18:33.923837 12282 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-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:18:33.930410 12282 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:33.930775 12282 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:33.931069 12282 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:33.931516 12282 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:33.931577 12282 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:33.931638 12282 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:33.931687 12282 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:33.936002 12282 rpc_server.cc:307] RPC server started. Bound to: 127.11.254.129:37959
I20260812 06:18:33.936040 12830 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.11.254.129:37959 every 8 connection(s)
I20260812 06:18:33.947928 12831 heartbeater.cc:344] Connected to a master server at 127.11.254.190:40727
I20260812 06:18:33.948046 12831 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:33.948261 12831 heartbeater.cc:507] Master 127.11.254.190:40727 requested a full tablet report, sending...
I20260812 06:18:33.948976 12637 ts_manager.cc:194] Registered new tserver with Master: bce5ced4082e4ea4a3b59684ba9eb740 (127.11.254.129:37959)
I20260812 06:18:33.949633 12282 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013203881s
I20260812 06:18:33.949772 12637 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:50400
I20260812 06:18:33.957470 12637 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:50402:
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:18:33.968303 12781 tablet_service.cc:1511] Processing CreateTablet for tablet 5156687fe1c04bba81b9be6acb486fee (DEFAULT_TABLE table=heavy-update-compaction-test [id=f90bddb4517443818904c948b37a7de5]), partition=
I20260812 06:18:33.968604 12781 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 5156687fe1c04bba81b9be6acb486fee. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:33.970685 12853 tablet_bootstrap.cc:492] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Bootstrap starting.
I20260812 06:18:33.971607 12853 tablet_bootstrap.cc:654] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:33.972692 12853 tablet_bootstrap.cc:492] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: No bootstrap required, opened a new log
I20260812 06:18:33.972862 12853 ts_tablet_manager.cc:1403] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:33.973302 12853 raft_consensus.cc:359] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bce5ced4082e4ea4a3b59684ba9eb740" member_type: VOTER last_known_addr { host: "127.11.254.129" port: 37959 } }
I20260812 06:18:33.973428 12853 raft_consensus.cc:385] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:33.973477 12853 raft_consensus.cc:740] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: bce5ced4082e4ea4a3b59684ba9eb740, State: Initialized, Role: FOLLOWER
I20260812 06:18:33.973624 12853 consensus_queue.cc:260] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740 [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: "bce5ced4082e4ea4a3b59684ba9eb740" member_type: VOTER last_known_addr { host: "127.11.254.129" port: 37959 } }
I20260812 06:18:33.973738 12853 raft_consensus.cc:399] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:33.973784 12853 raft_consensus.cc:493] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:33.973840 12853 raft_consensus.cc:3060] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:33.974607 12853 raft_consensus.cc:515] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bce5ced4082e4ea4a3b59684ba9eb740" member_type: VOTER last_known_addr { host: "127.11.254.129" port: 37959 } }
I20260812 06:18:33.974726 12853 leader_election.cc:304] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740 [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: bce5ced4082e4ea4a3b59684ba9eb740; no voters: 
I20260812 06:18:33.974887 12853 leader_election.cc:290] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:33.975023 12859 raft_consensus.cc:2804] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:33.975277 12859 raft_consensus.cc:697] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740 [term 1 LEADER]: Becoming Leader. State: Replica: bce5ced4082e4ea4a3b59684ba9eb740, State: Running, Role: LEADER
I20260812 06:18:33.975286 12853 ts_tablet_manager.cc:1434] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:33.975332 12831 heartbeater.cc:499] Master 127.11.254.190:40727 was elected leader, sending a full tablet report...
I20260812 06:18:33.975440 12859 consensus_queue.cc:237] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740 [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: "bce5ced4082e4ea4a3b59684ba9eb740" member_type: VOTER last_known_addr { host: "127.11.254.129" port: 37959 } }
I20260812 06:18:33.976881 12637 catalog_manager.cc:5719] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740 reported cstate change: term changed from 0 to 1, leader changed from <none> to bce5ced4082e4ea4a3b59684ba9eb740 (127.11.254.129). New cstate: current_term: 1 leader_uuid: "bce5ced4082e4ea4a3b59684ba9eb740" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bce5ced4082e4ea4a3b59684ba9eb740" member_type: VOTER last_known_addr { host: "127.11.254.129" port: 37959 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:34.040361 12282 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.015s	sys 0.011s
I20260812 06:18:34.186923 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling FlushMRSOp(5156687fe1c04bba81b9be6acb486fee): perf score=19.054940
I20260812 06:18:34.335496 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: FlushMRSOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.148s	user 0.094s	sys 0.051s Metrics: {"bytes_written":12307489,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":273,"dirs.run_wall_time_us":1168,"drs_written":1,"lbm_read_time_us":35,"lbm_reads_lt_1ms":4,"lbm_write_time_us":37064,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:18:34.336309 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling LogGCOp(5156687fe1c04bba81b9be6acb486fee): free 20743879 bytes of WAL
I20260812 06:18:34.336607 12744 log_reader.cc:385] T 5156687fe1c04bba81b9be6acb486fee: removed 2 log segments from log reader
I20260812 06:18:34.336686 12744 log.cc:1079] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5156687fe1c04bba81b9be6acb486fee/wal-000000001 (ops 1-6)
I20260812 06:18:34.336808 12744 log.cc:1079] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5156687fe1c04bba81b9be6acb486fee/wal-000000002 (ops 7-11)
I20260812 06:18:34.344139 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: LogGCOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.008s	user 0.007s	sys 0.000s Metrics: {}
I20260812 06:18:34.345499 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling UndoDeltaBlockGCOp(5156687fe1c04bba81b9be6acb486fee): 16411393 bytes on disk
I20260812 06:18:34.346110 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: UndoDeltaBlockGCOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":116,"lbm_reads_lt_1ms":4}
I20260812 06:18:34.349426 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee): perf score=2.188937
I20260812 06:18:34.370502 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.021s	user 0.004s	sys 0.012s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":7010,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.371080 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling MajorDeltaCompactionOp(5156687fe1c04bba81b9be6acb486fee): perf score=1.000000
I20260812 06:18:34.608198 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: MajorDeltaCompactionOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.237s	user 0.164s	sys 0.071s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672275,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":439,"lbm_read_time_us":16418,"lbm_reads_lt_1ms":460,"lbm_write_time_us":33601,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":328,"threads_started":5,"update_count":2000}
I20260812 06:18:34.608935 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee): perf score=22.032687
I20260812 06:18:34.710433 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.101s	user 0.058s	sys 0.041s Metrics: {"bytes_written":24614721,"delete_count":0,"lbm_write_time_us":43019,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":602,"reinsert_count":0,"update_count":3000}
I20260812 06:18:34.711051 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee): perf score=6.157687
I20260812 06:18:34.748605 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.037s	user 0.022s	sys 0.008s Metrics: {"bytes_written":8205079,"delete_count":0,"lbm_write_time_us":13460,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:34.749259 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee): perf score=2.188937
I20260812 06:18:34.767759 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.018s	user 0.009s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6931,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.768328 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling MajorDeltaCompactionOp(5156687fe1c04bba81b9be6acb486fee): perf score=1.000000
I20260812 06:18:35.048976 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: MajorDeltaCompactionOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.280s	user 0.196s	sys 0.084s Metrics: {"cfile_cache_miss":933,"cfile_cache_miss_bytes":41184453,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":854,"lbm_read_time_us":22119,"lbm_reads_lt_1ms":973,"lbm_write_time_us":50973,"lbm_writes_lt_1ms":943,"peak_mem_usage":112822188,"reinsert_count":0,"spinlock_wait_cycles":6784,"update_count":4500}
I20260812 06:18:35.049666 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee): perf score=22.032687
I20260812 06:18:35.125304 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.075s	user 0.037s	sys 0.028s Metrics: {"bytes_written":24614720,"delete_count":0,"lbm_write_time_us":29494,"lbm_writes_lt_1ms":603,"reinsert_count":0,"update_count":3000}
I20260812 06:18:35.125732 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee): perf score=6.157687
I20260812 06:18:35.152241 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.026s	user 0.018s	sys 0.004s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":10378,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:35.152848 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling MajorDeltaCompactionOp(5156687fe1c04bba81b9be6acb486fee): perf score=1.000000
I20260812 06:18:35.358847 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: MajorDeltaCompactionOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.206s	user 0.158s	sys 0.047s Metrics: {"cfile_cache_miss":832,"cfile_cache_miss_bytes":37081920,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":182,"lbm_read_time_us":14393,"lbm_reads_lt_1ms":864,"lbm_write_time_us":44814,"lbm_writes_lt_1ms":843,"mutex_wait_us":56,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":19712,"update_count":4000}
I20260812 06:18:35.359688 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee): perf score=18.063937
I20260812 06:18:35.435873 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.076s	user 0.030s	sys 0.030s Metrics: {"bytes_written":20512319,"delete_count":0,"lbm_write_time_us":28100,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":501,"reinsert_count":0,"update_count":2500}
I20260812 06:18:35.436374 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee): perf score=6.157687
I20260812 06:18:35.460148 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.024s	user 0.018s	sys 0.003s Metrics: {"bytes_written":8205079,"delete_count":0,"lbm_write_time_us":10028,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:35.460806 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling FlushMRSOp(5156687fe1c04bba81b9be6acb486fee): perf score=1.000000
I20260812 06:18:35.511296 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: FlushMRSOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.050s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":206,"dirs.run_wall_time_us":1482,"drs_written":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2650,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:35.511986 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling LogGCOp(5156687fe1c04bba81b9be6acb486fee): free 112692362 bytes of WAL
I20260812 06:18:35.512234 12744 log_reader.cc:385] T 5156687fe1c04bba81b9be6acb486fee: removed 11 log segments from log reader
I20260812 06:18:35.512300 12744 log.cc:1079] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5156687fe1c04bba81b9be6acb486fee/wal-000000003 (ops 12-16)
I20260812 06:18:35.512358 12744 log.cc:1079] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5156687fe1c04bba81b9be6acb486fee/wal-000000004 (ops 17-21)
I20260812 06:18:35.512457 12744 log.cc:1079] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5156687fe1c04bba81b9be6acb486fee/wal-000000005 (ops 22-26)
I20260812 06:18:35.512516 12744 log.cc:1079] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5156687fe1c04bba81b9be6acb486fee/wal-000000006 (ops 27-31)
I20260812 06:18:35.512557 12744 log.cc:1079] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5156687fe1c04bba81b9be6acb486fee/wal-000000007 (ops 32-36)
I20260812 06:18:35.512595 12744 log.cc:1079] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5156687fe1c04bba81b9be6acb486fee/wal-000000008 (ops 37-41)
I20260812 06:18:35.512632 12744 log.cc:1079] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5156687fe1c04bba81b9be6acb486fee/wal-000000009 (ops 42-46)
I20260812 06:18:35.512670 12744 log.cc:1079] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5156687fe1c04bba81b9be6acb486fee/wal-000000010 (ops 47-51)
I20260812 06:18:35.512707 12744 log.cc:1079] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5156687fe1c04bba81b9be6acb486fee/wal-000000011 (ops 52-56)
I20260812 06:18:35.512770 12744 log.cc:1079] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5156687fe1c04bba81b9be6acb486fee/wal-000000012 (ops 57-61)
I20260812 06:18:35.512811 12744 log.cc:1079] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5156687fe1c04bba81b9be6acb486fee/wal-000000013 (ops 62-66)
I20260812 06:18:35.538201 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: LogGCOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:35.538959 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee): perf score=6.157687
I20260812 06:18:35.566267 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.027s	user 0.015s	sys 0.010s Metrics: {"bytes_written":8410199,"delete_count":0,"lbm_write_time_us":11812,"lbm_writes_lt_1ms":208,"reinsert_count":0,"update_count":1025}
I20260812 06:18:35.566717 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling LogGCOp(5156687fe1c04bba81b9be6acb486fee): free 11564875 bytes of WAL
I20260812 06:18:35.566936 12744 log_reader.cc:385] T 5156687fe1c04bba81b9be6acb486fee: removed 1 log segments from log reader
I20260812 06:18:35.567000 12744 log.cc:1079] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5156687fe1c04bba81b9be6acb486fee/wal-000000014 (ops 67-70)
I20260812 06:18:35.569337 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: LogGCOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.002s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:35.569607 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee): perf score=2.188937
I20260812 06:18:35.583159 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.013s	user 0.006s	sys 0.006s Metrics: {"bytes_written":3897534,"delete_count":0,"lbm_write_time_us":4920,"lbm_writes_lt_1ms":98,"reinsert_count":0,"update_count":475}
I20260812 06:18:35.583583 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling UndoDeltaBlockGCOp(5156687fe1c04bba81b9be6acb486fee): 461 bytes on disk
I20260812 06:18:35.583978 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: UndoDeltaBlockGCOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:18:35.584391 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling MajorDeltaCompactionOp(5156687fe1c04bba81b9be6acb486fee): perf score=1.000000
I20260812 06:18:35.891937 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: MajorDeltaCompactionOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.307s	user 0.201s	sys 0.099s Metrics: {"cfile_cache_miss":1034,"cfile_cache_miss_bytes":45286991,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1146,"lbm_read_time_us":18225,"lbm_reads_lt_1ms":1074,"lbm_write_time_us":53774,"lbm_writes_lt_1ms":1043,"mutex_wait_us":321,"peak_mem_usage":125248760,"reinsert_count":0,"spinlock_wait_cycles":6144,"thread_start_us":395,"threads_started":6,"update_count":5000}
I20260812 06:18:35.892740 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee): perf score=24.017062
I20260812 06:18:35.970959 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.078s	user 0.036s	sys 0.036s Metrics: {"bytes_written":26214668,"delete_count":0,"lbm_write_time_us":33912,"lbm_writes_lt_1ms":642,"reinsert_count":0,"update_count":3195}
I20260812 06:18:35.971493 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee): perf score=5.165500
I20260812 06:18:35.991092 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.019s	user 0.013s	sys 0.004s Metrics: {"bytes_written":6605145,"delete_count":0,"lbm_write_time_us":7473,"lbm_writes_lt_1ms":164,"reinsert_count":0,"update_count":805}
I20260812 06:18:35.991519 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling MajorDeltaCompactionOp(5156687fe1c04bba81b9be6acb486fee): perf score=1.000000
I20260812 06:18:36.244242 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: MajorDeltaCompactionOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.253s	user 0.158s	sys 0.089s Metrics: {"cfile_cache_miss":832,"cfile_cache_miss_bytes":37081935,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":853,"lbm_read_time_us":18054,"lbm_reads_lt_1ms":872,"lbm_write_time_us":42235,"lbm_writes_lt_1ms":843,"mutex_wait_us":293,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":29952,"update_count":4000}
I20260812 06:18:36.244954 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee): perf score=22.032687
I20260812 06:18:36.310925 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.066s	user 0.044s	sys 0.020s Metrics: {"bytes_written":24614718,"delete_count":0,"lbm_write_time_us":29694,"lbm_writes_lt_1ms":603,"reinsert_count":0,"update_count":3000}
I20260812 06:18:36.311574 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee): perf score=2.188937
I20260812 06:18:36.328088 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.016s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6736,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.328610 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling MajorDeltaCompactionOp(5156687fe1c04bba81b9be6acb486fee): perf score=1.000000
I20260812 06:18:36.531524 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: MajorDeltaCompactionOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.203s	user 0.142s	sys 0.059s Metrics: {"cfile_cache_miss":732,"cfile_cache_miss_bytes":32979504,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":400,"lbm_read_time_us":15855,"lbm_reads_lt_1ms":772,"lbm_write_time_us":41194,"lbm_writes_lt_1ms":743,"mutex_wait_us":89,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":4608,"update_count":3500}
I20260812 06:18:36.532166 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee): perf score=15.087375
I20260812 06:18:36.572060 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.040s	user 0.031s	sys 0.005s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":17598,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:36.572582 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee): perf score=2.188937
I20260812 06:18:36.586208 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.013s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3751,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:36.586941 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling MajorDeltaCompactionOp(5156687fe1c04bba81b9be6acb486fee): perf score=1.000000
I20260812 06:18:36.738752 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: MajorDeltaCompactionOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.152s	user 0.108s	sys 0.038s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774675,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":231,"lbm_read_time_us":10038,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27561,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2500}
I20260812 06:18:36.739485 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee): perf score=14.095187
I20260812 06:18:36.784965 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.045s	user 0.028s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19187,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:36.785506 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee): perf score=2.188937
I20260812 06:18:36.801226 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.015s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5768,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.803151 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling MajorDeltaCompactionOp(5156687fe1c04bba81b9be6acb486fee): perf score=1.000000
I20260812 06:18:36.974772 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: MajorDeltaCompactionOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.171s	user 0.132s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":189,"lbm_read_time_us":12738,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27864,"lbm_writes_lt_1ms":543,"mutex_wait_us":30,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":29952,"update_count":2500}
I20260812 06:18:36.975544 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee): perf score=14.095187
I20260812 06:18:37.042809 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.067s	user 0.028s	sys 0.023s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":25535,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:37.043321 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee): perf score=2.188937
I20260812 06:18:37.054910 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4093,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.055471 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling FlushMRSOp(5156687fe1c04bba81b9be6acb486fee): perf score=1.000000
I20260812 06:18:37.088263 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: FlushMRSOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.033s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":51,"dirs.run_cpu_time_us":219,"dirs.run_wall_time_us":1262,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1850,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:37.088987 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling LogGCOp(5156687fe1c04bba81b9be6acb486fee): free 121006399 bytes of WAL
I20260812 06:18:37.089212 12744 log_reader.cc:385] T 5156687fe1c04bba81b9be6acb486fee: removed 12 log segments from log reader
I20260812 06:18:37.089258 12744 log.cc:1079] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5156687fe1c04bba81b9be6acb486fee/wal-000000015 (ops 71-75)
I20260812 06:18:37.089286 12744 log.cc:1079] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5156687fe1c04bba81b9be6acb486fee/wal-000000016 (ops 76-80)
I20260812 06:18:37.089349 12744 log.cc:1079] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5156687fe1c04bba81b9be6acb486fee/wal-000000017 (ops 81-85)
I20260812 06:18:37.089392 12744 log.cc:1079] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5156687fe1c04bba81b9be6acb486fee/wal-000000018 (ops 86-90)
I20260812 06:18:37.089433 12744 log.cc:1079] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5156687fe1c04bba81b9be6acb486fee/wal-000000019 (ops 91-95)
I20260812 06:18:37.089473 12744 log.cc:1079] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5156687fe1c04bba81b9be6acb486fee/wal-000000020 (ops 96-100)
I20260812 06:18:37.089514 12744 log.cc:1079] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5156687fe1c04bba81b9be6acb486fee/wal-000000021 (ops 101-104)
I20260812 06:18:37.089555 12744 log.cc:1079] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5156687fe1c04bba81b9be6acb486fee/wal-000000022 (ops 105-109)
I20260812 06:18:37.089594 12744 log.cc:1079] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5156687fe1c04bba81b9be6acb486fee/wal-000000023 (ops 110-114)
I20260812 06:18:37.089636 12744 log.cc:1079] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5156687fe1c04bba81b9be6acb486fee/wal-000000024 (ops 115-119)
I20260812 06:18:37.089680 12744 log.cc:1079] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5156687fe1c04bba81b9be6acb486fee/wal-000000025 (ops 120-124)
I20260812 06:18:37.089707 12744 log.cc:1079] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5156687fe1c04bba81b9be6acb486fee/wal-000000026 (ops 125-129)
I20260812 06:18:37.119488 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: LogGCOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.030s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:18:37.119938 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee): perf score=3.181125
I20260812 06:18:37.138803 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.019s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":7521,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:37.139235 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling LogGCOp(5156687fe1c04bba81b9be6acb486fee): free 12018006 bytes of WAL
I20260812 06:18:37.139441 12744 log_reader.cc:385] T 5156687fe1c04bba81b9be6acb486fee: removed 1 log segments from log reader
I20260812 06:18:37.139483 12744 log.cc:1079] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5156687fe1c04bba81b9be6acb486fee/wal-000000027 (ops 130-134)
I20260812 06:18:37.141991 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: LogGCOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:37.142293 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling UndoDeltaBlockGCOp(5156687fe1c04bba81b9be6acb486fee): 493 bytes on disk
I20260812 06:18:37.142678 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: UndoDeltaBlockGCOp(5156687fe1c04bba81b9be6acb486fee) 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:18:37.143142 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee): perf score=2.188937
I20260812 06:18:37.153450 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3525,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:37.153913 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling MajorDeltaCompactionOp(5156687fe1c04bba81b9be6acb486fee): perf score=1.000000
I20260812 06:18:37.374868 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: MajorDeltaCompactionOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.221s	user 0.132s	sys 0.088s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979738,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":523,"lbm_read_time_us":14887,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39344,"lbm_writes_lt_1ms":743,"mutex_wait_us":39,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":9600,"thread_start_us":106,"threads_started":1,"update_count":3500}
I20260812 06:18:37.375537 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee): perf score=18.063937
I20260812 06:18:37.438035 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.062s	user 0.036s	sys 0.023s Metrics: {"bytes_written":20512319,"delete_count":0,"lbm_write_time_us":26441,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:18:37.438565 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee): perf score=2.188937
I20260812 06:18:37.461403 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.023s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5103,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.461966 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee): perf score=2.188937
I20260812 06:18:37.476470 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5633,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.477052 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling MajorDeltaCompactionOp(5156687fe1c04bba81b9be6acb486fee): perf score=1.000000
I20260812 06:18:37.664902 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: MajorDeltaCompactionOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.188s	user 0.149s	sys 0.039s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979637,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":169,"lbm_read_time_us":13597,"lbm_reads_lt_1ms":773,"lbm_write_time_us":39976,"lbm_writes_lt_1ms":743,"mutex_wait_us":40,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":16000,"update_count":3500}
I20260812 06:18:37.666103 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee): perf score=15.087375
I20260812 06:18:37.720953 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.055s	user 0.037s	sys 0.017s Metrics: {"bytes_written":16656049,"delete_count":0,"lbm_write_time_us":24162,"lbm_writes_lt_1ms":409,"reinsert_count":0,"update_count":2030}
I20260812 06:18:37.721532 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee): perf score=2.188937
I20260812 06:18:37.744087 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.022s	user 0.011s	sys 0.004s Metrics: {"bytes_written":3856509,"delete_count":0,"lbm_write_time_us":6923,"lbm_writes_lt_1ms":97,"reinsert_count":0,"update_count":470}
I20260812 06:18:37.744623 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling MajorDeltaCompactionOp(5156687fe1c04bba81b9be6acb486fee): perf score=1.000000
I20260812 06:18:37.894196 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: MajorDeltaCompactionOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.149s	user 0.123s	sys 0.020s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":238,"lbm_read_time_us":9903,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28350,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14336,"update_count":2500}
I20260812 06:18:37.895059 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee): perf score=14.095187
I20260812 06:18:37.946588 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.051s	user 0.034s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21020,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:18:37.947103 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee): perf score=2.188937
I20260812 06:18:37.960212 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.013s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4381,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.961122 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling MajorDeltaCompactionOp(5156687fe1c04bba81b9be6acb486fee): perf score=1.000000
I20260812 06:18:38.159904 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: MajorDeltaCompactionOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.198s	user 0.148s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":201,"lbm_read_time_us":14166,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34535,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9216,"update_count":2500}
I20260812 06:18:38.160782 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee): perf score=14.095187
I20260812 06:18:38.241549 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.081s	user 0.051s	sys 0.025s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":34878,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:38.242425 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling MajorDeltaCompactionOp(5156687fe1c04bba81b9be6acb486fee): perf score=1.000000
I20260812 06:18:38.549314 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: MajorDeltaCompactionOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.307s	user 0.195s	sys 0.091s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1128,"lbm_read_time_us":20789,"lbm_reads_lt_1ms":463,"lbm_write_time_us":53075,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":441,"mutex_wait_us":566,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":23808,"update_count":2000}
I20260812 06:18:38.550426 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee): perf score=14.095187
I20260812 06:18:38.660298 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.110s	user 0.062s	sys 0.040s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":49156,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:38.661448 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee): perf score=2.188937
I20260812 06:18:38.722497 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.060s	user 0.028s	sys 0.020s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":15688,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.724066 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling FlushMRSOp(5156687fe1c04bba81b9be6acb486fee): perf score=1.000000
I20260812 06:18:38.796846 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: FlushMRSOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.072s	user 0.045s	sys 0.001s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":81,"dirs.run_cpu_time_us":386,"dirs.run_wall_time_us":1706,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":5494,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:38.798102 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling LogGCOp(5156687fe1c04bba81b9be6acb486fee): free 108082635 bytes of WAL
I20260812 06:18:38.798610 12744 log_reader.cc:385] T 5156687fe1c04bba81b9be6acb486fee: removed 11 log segments from log reader
I20260812 06:18:38.798684 12744 log.cc:1079] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5156687fe1c04bba81b9be6acb486fee/wal-000000028 (ops 135-139)
I20260812 06:18:38.798763 12744 log.cc:1079] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5156687fe1c04bba81b9be6acb486fee/wal-000000029 (ops 140-144)
I20260812 06:18:38.798847 12744 log.cc:1079] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5156687fe1c04bba81b9be6acb486fee/wal-000000030 (ops 145-148)
I20260812 06:18:38.798905 12744 log.cc:1079] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5156687fe1c04bba81b9be6acb486fee/wal-000000031 (ops 149-153)
I20260812 06:18:38.798995 12744 log.cc:1079] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5156687fe1c04bba81b9be6acb486fee/wal-000000032 (ops 154-158)
I20260812 06:18:38.799067 12744 log.cc:1079] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5156687fe1c04bba81b9be6acb486fee/wal-000000033 (ops 159-162)
I20260812 06:18:38.799156 12744 log.cc:1079] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5156687fe1c04bba81b9be6acb486fee/wal-000000034 (ops 163-167)
I20260812 06:18:38.799260 12744 log.cc:1079] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5156687fe1c04bba81b9be6acb486fee/wal-000000035 (ops 168-172)
I20260812 06:18:38.799360 12744 log.cc:1079] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5156687fe1c04bba81b9be6acb486fee/wal-000000036 (ops 173-176)
I20260812 06:18:38.799464 12744 log.cc:1079] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5156687fe1c04bba81b9be6acb486fee/wal-000000037 (ops 177-181)
I20260812 06:18:38.799564 12744 log.cc:1079] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5156687fe1c04bba81b9be6acb486fee/wal-000000038 (ops 182-186)
I20260812 06:18:38.837023 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: LogGCOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.039s	user 0.000s	sys 0.038s Metrics: {}
I20260812 06:18:38.837826 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee): perf score=5.165500
I20260812 06:18:38.869714 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.032s	user 0.022s	sys 0.008s Metrics: {"bytes_written":7015376,"delete_count":0,"lbm_write_time_us":13577,"lbm_writes_lt_1ms":174,"reinsert_count":0,"update_count":855}
I20260812 06:18:38.870929 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling LogGCOp(5156687fe1c04bba81b9be6acb486fee): free 8767086 bytes of WAL
I20260812 06:18:38.871291 12744 log_reader.cc:385] T 5156687fe1c04bba81b9be6acb486fee: removed 1 log segments from log reader
I20260812 06:18:38.871410 12744 log.cc:1079] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: Deleting log segment in path: /tmp/dist-test-task4GoS2n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515508300066-12282-0/minicluster-data/ts-0-root/wals/5156687fe1c04bba81b9be6acb486fee/wal-000000039 (ops 187-191)
I20260812 06:18:38.875283 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: LogGCOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:38.876127 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling UndoDeltaBlockGCOp(5156687fe1c04bba81b9be6acb486fee): 463 bytes on disk
I20260812 06:18:38.877231 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: UndoDeltaBlockGCOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":219,"lbm_reads_lt_1ms":4}
I20260812 06:18:38.878693 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee): perf score=1.000000
I20260812 06:18:38.897061 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.018s	user 0.011s	sys 0.003s Metrics: {"bytes_written":1189877,"delete_count":0,"lbm_write_time_us":4272,"lbm_writes_lt_1ms":32,"reinsert_count":0,"update_count":145}
I20260812 06:18:38.897940 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling MajorDeltaCompactionOp(5156687fe1c04bba81b9be6acb486fee): perf score=1.000000
I20260812 06:18:39.328312 12282 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.288s	user 1.931s	sys 0.147s
I20260812 06:18:39.352041 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: MajorDeltaCompactionOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.454s	user 0.270s	sys 0.169s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979679,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1868,"lbm_read_time_us":33389,"lbm_reads_lt_1ms":766,"lbm_write_time_us":75729,"lbm_writes_lt_1ms":743,"mutex_wait_us":78,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":37248,"thread_start_us":924,"threads_started":7,"update_count":3500}
I20260812 06:18:39.353488 12832 maintenance_manager.cc:419] P bce5ced4082e4ea4a3b59684ba9eb740: Scheduling FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee): perf score=18.063937
I20260812 06:18:39.410771 12282 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.082s	user 0.002s	sys 0.000s
I20260812 06:18:39.411341 12282 tablet_server.cc:179] TabletServer@127.11.254.129:0 shutting down...
I20260812 06:18:39.432798 12744 maintenance_manager.cc:643] P bce5ced4082e4ea4a3b59684ba9eb740: FlushDeltaMemStoresOp(5156687fe1c04bba81b9be6acb486fee) complete. Timing: real 0.079s	user 0.064s	sys 0.011s Metrics: {"bytes_written":20512319,"delete_count":0,"lbm_write_time_us":35966,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:39.433472 12282 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:39.433722 12282 tablet_replica.cc:333] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740: stopping tablet replica
I20260812 06:18:39.433903 12282 raft_consensus.cc:2243] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:39.434098 12282 raft_consensus.cc:2272] T 5156687fe1c04bba81b9be6acb486fee P bce5ced4082e4ea4a3b59684ba9eb740 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:39.437605 12282 tablet_server.cc:196] TabletServer@127.11.254.129:0 shutdown complete.
I20260812 06:18:39.440251 12282 master.cc:562] Master@127.11.254.190:40727 shutting down...
I20260812 06:18:39.444211 12282 raft_consensus.cc:2243] T 00000000000000000000000000000000 P a2754903350b477d85813f80f2e8843b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:39.444386 12282 raft_consensus.cc:2272] T 00000000000000000000000000000000 P a2754903350b477d85813f80f2e8843b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:39.444480 12282 tablet_replica.cc:333] T 00000000000000000000000000000000 P a2754903350b477d85813f80f2e8843b: stopping tablet replica
I20260812 06:18:39.458173 12282 master.cc:584] Master@127.11.254.190:40727 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5731 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11240 ms total)

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