[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:19:39.922171 22535 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.22.1.254:38101
I20260812 06:19:39.923179 22535 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:19:39.923781 22535 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:39.929983 22554 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:39.929989 22556 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:39.930043 22535 server_base.cc:1061] running on GCE node
W20260812 06:19:39.930235 22551 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:39.930703 22535 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:39.930789 22535 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:39.930830 22535 hybrid_clock.cc:648] HybridClock initialized: now 1786515579930829 us; error 0 us; skew 500 ppm
I20260812 06:19:39.932502 22535 webserver.cc:533] Webserver started at http://127.22.1.254:32779/ using document root <none> and password file <none>
I20260812 06:19:39.932992 22535 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:39.933046 22535 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:39.933240 22535 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:39.934860 22535 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/master-0-root/instance:
uuid: "b390c8371d7341269737980c82747703"
format_stamp: "Formatted at 2026-08-12 06:19:39 on dist-test-slave-7lbf"
I20260812 06:19:39.938269 22535 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.001s	sys 0.003s
I20260812 06:19:39.940202 22562 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:39.941146 22535 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.001s
I20260812 06:19:39.941239 22535 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/master-0-root
uuid: "b390c8371d7341269737980c82747703"
format_stamp: "Formatted at 2026-08-12 06:19:39 on dist-test-slave-7lbf"
I20260812 06:19:39.941318 22535 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:39.956648 22535 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:39.957206 22535 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:19:39.957333 22535 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:39.964298 22645 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.22.1.254:38101 every 8 connection(s)
I20260812 06:19:39.964305 22535 rpc_server.cc:307] RPC server started. Bound to: 127.22.1.254:38101
I20260812 06:19:39.966625 22646 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:39.971771 22646 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b390c8371d7341269737980c82747703: Bootstrap starting.
I20260812 06:19:39.974014 22646 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P b390c8371d7341269737980c82747703: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:39.974869 22646 log.cc:826] T 00000000000000000000000000000000 P b390c8371d7341269737980c82747703: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:39.976404 22646 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b390c8371d7341269737980c82747703: No bootstrap required, opened a new log
I20260812 06:19:39.979091 22646 raft_consensus.cc:359] T 00000000000000000000000000000000 P b390c8371d7341269737980c82747703 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b390c8371d7341269737980c82747703" member_type: VOTER }
I20260812 06:19:39.979245 22646 raft_consensus.cc:385] T 00000000000000000000000000000000 P b390c8371d7341269737980c82747703 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:39.979310 22646 raft_consensus.cc:740] T 00000000000000000000000000000000 P b390c8371d7341269737980c82747703 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b390c8371d7341269737980c82747703, State: Initialized, Role: FOLLOWER
I20260812 06:19:39.979919 22646 consensus_queue.cc:260] T 00000000000000000000000000000000 P b390c8371d7341269737980c82747703 [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: "b390c8371d7341269737980c82747703" member_type: VOTER }
I20260812 06:19:39.980072 22646 raft_consensus.cc:399] T 00000000000000000000000000000000 P b390c8371d7341269737980c82747703 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:39.980135 22646 raft_consensus.cc:493] T 00000000000000000000000000000000 P b390c8371d7341269737980c82747703 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:39.980253 22646 raft_consensus.cc:3060] T 00000000000000000000000000000000 P b390c8371d7341269737980c82747703 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:39.980971 22646 raft_consensus.cc:515] T 00000000000000000000000000000000 P b390c8371d7341269737980c82747703 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b390c8371d7341269737980c82747703" member_type: VOTER }
I20260812 06:19:39.981380 22646 leader_election.cc:304] T 00000000000000000000000000000000 P b390c8371d7341269737980c82747703 [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: b390c8371d7341269737980c82747703; no voters: 
I20260812 06:19:39.981700 22646 leader_election.cc:290] T 00000000000000000000000000000000 P b390c8371d7341269737980c82747703 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:39.981805 22650 raft_consensus.cc:2804] T 00000000000000000000000000000000 P b390c8371d7341269737980c82747703 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:39.982033 22650 raft_consensus.cc:697] T 00000000000000000000000000000000 P b390c8371d7341269737980c82747703 [term 1 LEADER]: Becoming Leader. State: Replica: b390c8371d7341269737980c82747703, State: Running, Role: LEADER
I20260812 06:19:39.982502 22650 consensus_queue.cc:237] T 00000000000000000000000000000000 P b390c8371d7341269737980c82747703 [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: "b390c8371d7341269737980c82747703" member_type: VOTER }
I20260812 06:19:39.982694 22646 sys_catalog.cc:565] T 00000000000000000000000000000000 P b390c8371d7341269737980c82747703 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:39.984284 22651 sys_catalog.cc:455] T 00000000000000000000000000000000 P b390c8371d7341269737980c82747703 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "b390c8371d7341269737980c82747703" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b390c8371d7341269737980c82747703" member_type: VOTER } }
I20260812 06:19:39.984330 22652 sys_catalog.cc:455] T 00000000000000000000000000000000 P b390c8371d7341269737980c82747703 [sys.catalog]: SysCatalogTable state changed. Reason: New leader b390c8371d7341269737980c82747703. Latest consensus state: current_term: 1 leader_uuid: "b390c8371d7341269737980c82747703" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b390c8371d7341269737980c82747703" member_type: VOTER } }
I20260812 06:19:39.984401 22651 sys_catalog.cc:458] T 00000000000000000000000000000000 P b390c8371d7341269737980c82747703 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:39.984426 22652 sys_catalog.cc:458] T 00000000000000000000000000000000 P b390c8371d7341269737980c82747703 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:39.984733 22675 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:39.984818 22535 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:39.986886 22675 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:39.991349 22675 catalog_manager.cc:1383] Generated new cluster ID: cd8f72f321664e17b11e9a614914a7ba
I20260812 06:19:39.991411 22675 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:40.000435 22675 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:40.001564 22675 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:40.011723 22675 catalog_manager.cc:6092] T 00000000000000000000000000000000 P b390c8371d7341269737980c82747703: Generated new TSK 0
I20260812 06:19:40.012521 22675 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:40.017367 22535 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:40.020330 22690 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:40.020304 22688 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:40.020321 22695 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:40.020493 22535 server_base.cc:1061] running on GCE node
I20260812 06:19:40.020849 22535 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:40.020915 22535 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:40.020946 22535 hybrid_clock.cc:648] HybridClock initialized: now 1786515580020945 us; error 0 us; skew 500 ppm
I20260812 06:19:40.021849 22535 webserver.cc:533] Webserver started at http://127.22.1.193:43151/ using document root <none> and password file <none>
I20260812 06:19:40.022024 22535 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:40.022078 22535 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:40.022150 22535 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:40.022565 22535 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/instance:
uuid: "d0ce05ba010244d1b54e05f706ccb92d"
format_stamp: "Formatted at 2026-08-12 06:19:40 on dist-test-slave-7lbf"
I20260812 06:19:40.024303 22535 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:40.025336 22700 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:40.025602 22535 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:40.025666 22535 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root
uuid: "d0ce05ba010244d1b54e05f706ccb92d"
format_stamp: "Formatted at 2026-08-12 06:19:40 on dist-test-slave-7lbf"
I20260812 06:19:40.025732 22535 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:40.032461 22535 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:40.032835 22535 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:40.033234 22535 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:40.034106 22535 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:40.034157 22535 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:40.034204 22535 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:40.034233 22535 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:40.040666 22535 rpc_server.cc:307] RPC server started. Bound to: 127.22.1.193:35135
I20260812 06:19:40.040710 22810 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.22.1.193:35135 every 8 connection(s)
I20260812 06:19:40.050362 22811 heartbeater.cc:344] Connected to a master server at 127.22.1.254:38101
I20260812 06:19:40.050604 22811 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:40.051012 22811 heartbeater.cc:507] Master 127.22.1.254:38101 requested a full tablet report, sending...
I20260812 06:19:40.052358 22591 ts_manager.cc:194] Registered new tserver with Master: d0ce05ba010244d1b54e05f706ccb92d (127.22.1.193:35135)
I20260812 06:19:40.052438 22535 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011150347s
I20260812 06:19:40.053485 22591 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:46072
I20260812 06:19:40.061774 22591 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:46080:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:40.074733 22742 tablet_service.cc:1511] Processing CreateTablet for tablet 2facba7b224945e2a0c46626c20af092 (DEFAULT_TABLE table=heavy-update-compaction-test [id=3afc49825d08495889dc6b4c9d324e73]), partition=
I20260812 06:19:40.075165 22742 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 2facba7b224945e2a0c46626c20af092. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:40.077181 22830 tablet_bootstrap.cc:492] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Bootstrap starting.
I20260812 06:19:40.078099 22830 tablet_bootstrap.cc:654] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:40.079294 22830 tablet_bootstrap.cc:492] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: No bootstrap required, opened a new log
I20260812 06:19:40.079383 22830 ts_tablet_manager.cc:1403] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:40.079751 22830 raft_consensus.cc:359] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d0ce05ba010244d1b54e05f706ccb92d" member_type: VOTER last_known_addr { host: "127.22.1.193" port: 35135 } }
I20260812 06:19:40.079842 22830 raft_consensus.cc:385] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:40.079873 22830 raft_consensus.cc:740] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d0ce05ba010244d1b54e05f706ccb92d, State: Initialized, Role: FOLLOWER
I20260812 06:19:40.080009 22830 consensus_queue.cc:260] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d [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: "d0ce05ba010244d1b54e05f706ccb92d" member_type: VOTER last_known_addr { host: "127.22.1.193" port: 35135 } }
I20260812 06:19:40.080088 22830 raft_consensus.cc:399] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:40.080132 22830 raft_consensus.cc:493] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:40.080178 22830 raft_consensus.cc:3060] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:40.080832 22830 raft_consensus.cc:515] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d0ce05ba010244d1b54e05f706ccb92d" member_type: VOTER last_known_addr { host: "127.22.1.193" port: 35135 } }
I20260812 06:19:40.080953 22830 leader_election.cc:304] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d [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: d0ce05ba010244d1b54e05f706ccb92d; no voters: 
I20260812 06:19:40.081151 22830 leader_election.cc:290] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:40.081259 22832 raft_consensus.cc:2804] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:40.081455 22830 ts_tablet_manager.cc:1434] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:40.081496 22832 raft_consensus.cc:697] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d [term 1 LEADER]: Becoming Leader. State: Replica: d0ce05ba010244d1b54e05f706ccb92d, State: Running, Role: LEADER
I20260812 06:19:40.081708 22811 heartbeater.cc:499] Master 127.22.1.254:38101 was elected leader, sending a full tablet report...
I20260812 06:19:40.081663 22832 consensus_queue.cc:237] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d [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: "d0ce05ba010244d1b54e05f706ccb92d" member_type: VOTER last_known_addr { host: "127.22.1.193" port: 35135 } }
I20260812 06:19:40.084192 22591 catalog_manager.cc:5719] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d reported cstate change: term changed from 0 to 1, leader changed from <none> to d0ce05ba010244d1b54e05f706ccb92d (127.22.1.193). New cstate: current_term: 1 leader_uuid: "d0ce05ba010244d1b54e05f706ccb92d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d0ce05ba010244d1b54e05f706ccb92d" member_type: VOTER last_known_addr { host: "127.22.1.193" port: 35135 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:40.142024 22535 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.014s	sys 0.010s
I20260812 06:19:40.291733 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushMRSOp(2facba7b224945e2a0c46626c20af092): perf score=19.054940
I20260812 06:19:40.444002 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushMRSOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.152s	user 0.125s	sys 0.020s Metrics: {"bytes_written":11897249,"cfile_init":1,"compiler_manager_pool.queue_time_us":216,"delete_count":0,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":215,"dirs.run_wall_time_us":1046,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":37746,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"thread_start_us":111,"threads_started":1,"update_count":1450}
I20260812 06:19:40.445178 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling LogGCOp(2facba7b224945e2a0c46626c20af092): free 20743880 bytes of WAL
I20260812 06:19:40.445478 22706 log_reader.cc:385] T 2facba7b224945e2a0c46626c20af092: removed 2 log segments from log reader
I20260812 06:19:40.445570 22706 log.cc:1079] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/2facba7b224945e2a0c46626c20af092/wal-000000001 (ops 1-6)
I20260812 06:19:40.445634 22706 log.cc:1079] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/2facba7b224945e2a0c46626c20af092/wal-000000002 (ops 7-11)
I20260812 06:19:40.450840 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: LogGCOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.006s	user 0.001s	sys 0.003s Metrics: {}
I20260812 06:19:40.451182 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling UndoDeltaBlockGCOp(2facba7b224945e2a0c46626c20af092): 16821647 bytes on disk
I20260812 06:19:40.451968 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: UndoDeltaBlockGCOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":94,"lbm_reads_lt_1ms":4}
I20260812 06:19:40.452400 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=2.188937
I20260812 06:19:40.470685 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.018s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6078,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.471164 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling MajorDeltaCompactionOp(2facba7b224945e2a0c46626c20af092): perf score=1.000000
I20260812 06:19:40.610683 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: MajorDeltaCompactionOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.139s	user 0.100s	sys 0.035s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20303031,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":583,"lbm_read_time_us":9244,"lbm_reads_lt_1ms":450,"lbm_write_time_us":23544,"lbm_writes_lt_1ms":433,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":6912,"thread_start_us":325,"threads_started":5,"update_count":1950}
I20260812 06:19:40.611382 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=10.126437
I20260812 06:19:40.650034 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.038s	user 0.021s	sys 0.015s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":18654,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:40.650450 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=2.188937
I20260812 06:19:40.662245 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4442,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.662684 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling MajorDeltaCompactionOp(2facba7b224945e2a0c46626c20af092): perf score=1.000000
I20260812 06:19:40.780230 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: MajorDeltaCompactionOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.117s	user 0.097s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713274,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":679,"lbm_read_time_us":8505,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23543,"lbm_writes_lt_1ms":443,"mutex_wait_us":58,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:40.780797 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=10.126437
I20260812 06:19:40.817975 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.037s	user 0.017s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16511,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:40.818411 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=2.188937
I20260812 06:19:40.836800 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.018s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5128,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.837316 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling MajorDeltaCompactionOp(2facba7b224945e2a0c46626c20af092): perf score=1.000000
I20260812 06:19:40.951889 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: MajorDeltaCompactionOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.114s	user 0.080s	sys 0.034s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":280,"lbm_read_time_us":7165,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22436,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:40.952376 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=11.118625
I20260812 06:19:41.005028 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.052s	user 0.025s	sys 0.020s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":19241,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:19:41.005475 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=3.181125
I20260812 06:19:41.022167 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.016s	user 0.015s	sys 0.001s Metrics: {"bytes_written":4923142,"delete_count":0,"lbm_write_time_us":6716,"lbm_writes_lt_1ms":123,"reinsert_count":0,"update_count":600}
I20260812 06:19:41.022622 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=1.196750
I20260812 06:19:41.030592 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.008s	user 0.003s	sys 0.004s Metrics: {"bytes_written":2871905,"delete_count":0,"lbm_write_time_us":2787,"lbm_writes_lt_1ms":73,"reinsert_count":0,"update_count":350}
I20260812 06:19:41.031068 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling MajorDeltaCompactionOp(2facba7b224945e2a0c46626c20af092): perf score=1.000000
I20260812 06:19:41.211288 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: MajorDeltaCompactionOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.180s	user 0.119s	sys 0.049s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815776,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":624,"lbm_read_time_us":11944,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32403,"lbm_writes_lt_1ms":543,"mutex_wait_us":232,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2500}
I20260812 06:19:41.211752 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=14.095187
I20260812 06:19:41.264519 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.053s	user 0.017s	sys 0.028s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":17333,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:41.265101 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=2.188937
I20260812 06:19:41.275378 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3861,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.275874 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling MajorDeltaCompactionOp(2facba7b224945e2a0c46626c20af092): perf score=1.000000
I20260812 06:19:41.447182 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: MajorDeltaCompactionOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.171s	user 0.094s	sys 0.072s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":64,"lbm_read_time_us":11607,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28471,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:41.447702 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=11.118625
I20260812 06:19:41.477998 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.030s	user 0.015s	sys 0.015s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":12326,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:41.478466 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=2.188937
I20260812 06:19:41.505105 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.026s	user 0.010s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3762,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:41.505651 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=2.188937
I20260812 06:19:41.520522 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5696,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.521078 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling MajorDeltaCompactionOp(2facba7b224945e2a0c46626c20af092): perf score=1.000000
I20260812 06:19:41.672690 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: MajorDeltaCompactionOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.151s	user 0.099s	sys 0.052s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":133,"lbm_read_time_us":11244,"lbm_reads_lt_1ms":573,"lbm_write_time_us":25797,"lbm_writes_lt_1ms":543,"mutex_wait_us":35,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5760,"update_count":2500}
I20260812 06:19:41.673362 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=11.118625
I20260812 06:19:41.705209 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.032s	user 0.017s	sys 0.012s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":13125,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:41.705770 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=2.188937
I20260812 06:19:41.725065 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.019s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4356,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.725564 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=2.188937
I20260812 06:19:41.748816 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.023s	user 0.008s	sys 0.012s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4974,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:41.749388 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushMRSOp(2facba7b224945e2a0c46626c20af092): perf score=1.000000
I20260812 06:19:41.794034 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushMRSOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.044s	user 0.031s	sys 0.001s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":48,"dirs.run_cpu_time_us":182,"dirs.run_wall_time_us":1239,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1535,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:41.794989 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling LogGCOp(2facba7b224945e2a0c46626c20af092): free 124710302 bytes of WAL
I20260812 06:19:41.795243 22706 log_reader.cc:385] T 2facba7b224945e2a0c46626c20af092: removed 12 log segments from log reader
I20260812 06:19:41.795295 22706 log.cc:1079] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/2facba7b224945e2a0c46626c20af092/wal-000000003 (ops 12-16)
I20260812 06:19:41.795332 22706 log.cc:1079] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/2facba7b224945e2a0c46626c20af092/wal-000000004 (ops 17-21)
I20260812 06:19:41.795367 22706 log.cc:1079] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/2facba7b224945e2a0c46626c20af092/wal-000000005 (ops 22-26)
I20260812 06:19:41.795403 22706 log.cc:1079] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/2facba7b224945e2a0c46626c20af092/wal-000000006 (ops 27-31)
I20260812 06:19:41.795426 22706 log.cc:1079] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/2facba7b224945e2a0c46626c20af092/wal-000000007 (ops 32-36)
I20260812 06:19:41.795447 22706 log.cc:1079] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/2facba7b224945e2a0c46626c20af092/wal-000000008 (ops 37-41)
I20260812 06:19:41.795475 22706 log.cc:1079] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/2facba7b224945e2a0c46626c20af092/wal-000000009 (ops 42-46)
I20260812 06:19:41.795506 22706 log.cc:1079] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/2facba7b224945e2a0c46626c20af092/wal-000000010 (ops 47-51)
I20260812 06:19:41.795535 22706 log.cc:1079] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/2facba7b224945e2a0c46626c20af092/wal-000000011 (ops 52-56)
I20260812 06:19:41.795567 22706 log.cc:1079] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/2facba7b224945e2a0c46626c20af092/wal-000000012 (ops 57-61)
I20260812 06:19:41.795598 22706 log.cc:1079] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/2facba7b224945e2a0c46626c20af092/wal-000000013 (ops 62-66)
I20260812 06:19:41.795629 22706 log.cc:1079] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/2facba7b224945e2a0c46626c20af092/wal-000000014 (ops 67-71)
I20260812 06:19:41.818495 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: LogGCOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.023s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:19:41.818940 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=3.181125
I20260812 06:19:41.840600 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.021s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":6494,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:41.841089 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling UndoDeltaBlockGCOp(2facba7b224945e2a0c46626c20af092): 483 bytes on disk
I20260812 06:19:41.841480 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: UndoDeltaBlockGCOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:19:41.841975 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=2.188937
I20260812 06:19:41.851105 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.009s	user 0.003s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3284,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:41.851526 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling MajorDeltaCompactionOp(2facba7b224945e2a0c46626c20af092): perf score=1.000000
I20260812 06:19:42.104465 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: MajorDeltaCompactionOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.253s	user 0.159s	sys 0.084s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020845,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":287,"lbm_read_time_us":14676,"lbm_reads_lt_1ms":775,"lbm_write_time_us":43667,"lbm_writes_lt_1ms":743,"mutex_wait_us":2,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1920,"thread_start_us":82,"threads_started":1,"update_count":3500}
I20260812 06:19:42.105075 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=18.063937
I20260812 06:19:42.168507 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.063s	user 0.037s	sys 0.016s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":25650,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:42.169045 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=2.188937
I20260812 06:19:42.187353 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.018s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7138,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.187887 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling MajorDeltaCompactionOp(2facba7b224945e2a0c46626c20af092): perf score=1.000000
I20260812 06:19:42.409188 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: MajorDeltaCompactionOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.221s	user 0.135s	sys 0.081s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918097,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":143,"lbm_read_time_us":14734,"lbm_reads_lt_1ms":672,"lbm_write_time_us":37142,"lbm_writes_lt_1ms":643,"mutex_wait_us":33,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13184,"update_count":3000}
I20260812 06:19:42.409713 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=18.063937
I20260812 06:19:42.458032 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.048s	user 0.018s	sys 0.029s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":21587,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:42.458526 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling MajorDeltaCompactionOp(2facba7b224945e2a0c46626c20af092): perf score=1.000000
I20260812 06:19:42.619004 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: MajorDeltaCompactionOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.160s	user 0.119s	sys 0.041s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24815567,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":167,"lbm_read_time_us":12390,"lbm_reads_lt_1ms":563,"lbm_write_time_us":26526,"lbm_writes_lt_1ms":543,"mutex_wait_us":66,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:19:42.619536 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=14.095187
I20260812 06:19:42.674785 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.055s	user 0.036s	sys 0.018s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20547,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:42.675305 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=2.188937
I20260812 06:19:42.685731 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3767,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.686280 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling MajorDeltaCompactionOp(2facba7b224945e2a0c46626c20af092): perf score=1.000000
I20260812 06:19:42.858812 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: MajorDeltaCompactionOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.172s	user 0.111s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":593,"lbm_read_time_us":11131,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26201,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:19:42.859325 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=14.095187
I20260812 06:19:42.908228 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.049s	user 0.026s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19435,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:42.908802 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=2.188937
I20260812 06:19:42.926419 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.017s	user 0.002s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3808,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.926954 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling MajorDeltaCompactionOp(2facba7b224945e2a0c46626c20af092): perf score=1.000000
I20260812 06:19:43.094210 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: MajorDeltaCompactionOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.167s	user 0.091s	sys 0.076s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":161,"lbm_read_time_us":12611,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27322,"lbm_writes_lt_1ms":543,"mutex_wait_us":36,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":2500}
I20260812 06:19:43.095070 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=11.118625
I20260812 06:19:43.129485 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.034s	user 0.020s	sys 0.011s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":14408,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:43.130050 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=2.188937
I20260812 06:19:43.143709 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.013s	user 0.010s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5009,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:43.144282 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushMRSOp(2facba7b224945e2a0c46626c20af092): perf score=1.000000
I20260812 06:19:43.183164 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushMRSOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.039s	user 0.024s	sys 0.000s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":258,"dirs.run_wall_time_us":1296,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1630,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:43.184170 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=3.181125
I20260812 06:19:43.204250 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.020s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":3828,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:43.204787 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling LogGCOp(2facba7b224945e2a0c46626c20af092): free 116849521 bytes of WAL
I20260812 06:19:43.205035 22706 log_reader.cc:385] T 2facba7b224945e2a0c46626c20af092: removed 12 log segments from log reader
I20260812 06:19:43.205083 22706 log.cc:1079] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/2facba7b224945e2a0c46626c20af092/wal-000000015 (ops 72-76)
I20260812 06:19:43.205121 22706 log.cc:1079] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/2facba7b224945e2a0c46626c20af092/wal-000000016 (ops 77-80)
I20260812 06:19:43.205153 22706 log.cc:1079] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/2facba7b224945e2a0c46626c20af092/wal-000000017 (ops 81-85)
I20260812 06:19:43.205185 22706 log.cc:1079] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/2facba7b224945e2a0c46626c20af092/wal-000000018 (ops 86-90)
I20260812 06:19:43.205216 22706 log.cc:1079] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/2facba7b224945e2a0c46626c20af092/wal-000000019 (ops 91-94)
I20260812 06:19:43.205246 22706 log.cc:1079] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/2facba7b224945e2a0c46626c20af092/wal-000000020 (ops 95-99)
I20260812 06:19:43.205276 22706 log.cc:1079] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/2facba7b224945e2a0c46626c20af092/wal-000000021 (ops 100-104)
I20260812 06:19:43.205305 22706 log.cc:1079] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/2facba7b224945e2a0c46626c20af092/wal-000000022 (ops 105-108)
I20260812 06:19:43.205334 22706 log.cc:1079] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/2facba7b224945e2a0c46626c20af092/wal-000000023 (ops 109-113)
I20260812 06:19:43.205365 22706 log.cc:1079] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/2facba7b224945e2a0c46626c20af092/wal-000000024 (ops 114-118)
I20260812 06:19:43.205399 22706 log.cc:1079] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/2facba7b224945e2a0c46626c20af092/wal-000000025 (ops 119-123)
I20260812 06:19:43.205428 22706 log.cc:1079] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/2facba7b224945e2a0c46626c20af092/wal-000000026 (ops 124-128)
I20260812 06:19:43.227411 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: LogGCOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.022s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:19:43.227886 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling UndoDeltaBlockGCOp(2facba7b224945e2a0c46626c20af092): 447 bytes on disk
I20260812 06:19:43.228297 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: UndoDeltaBlockGCOp(2facba7b224945e2a0c46626c20af092) 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:19:43.228797 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=2.188937
I20260812 06:19:43.241850 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.013s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3739,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.242323 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling LogGCOp(2facba7b224945e2a0c46626c20af092): free 11564891 bytes of WAL
I20260812 06:19:43.242556 22706 log_reader.cc:385] T 2facba7b224945e2a0c46626c20af092: removed 1 log segments from log reader
I20260812 06:19:43.242604 22706 log.cc:1079] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/2facba7b224945e2a0c46626c20af092/wal-000000027 (ops 129-132)
I20260812 06:19:43.244405 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: LogGCOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:43.244766 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling MajorDeltaCompactionOp(2facba7b224945e2a0c46626c20af092): perf score=1.000000
I20260812 06:19:43.426419 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: MajorDeltaCompactionOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.181s	user 0.120s	sys 0.059s Metrics: {"cfile_cache_miss":644,"cfile_cache_miss_bytes":29328568,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":699,"lbm_read_time_us":12705,"lbm_reads_lt_1ms":676,"lbm_write_time_us":31047,"lbm_writes_lt_1ms":653,"peak_mem_usage":75952822,"reinsert_count":0,"spinlock_wait_cycles":11136,"thread_start_us":75,"threads_started":1,"update_count":3050}
I20260812 06:19:43.426915 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=18.063937
I20260812 06:19:43.485392 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.058s	user 0.038s	sys 0.016s Metrics: {"bytes_written":20102072,"delete_count":0,"lbm_write_time_us":25210,"lbm_writes_lt_1ms":493,"reinsert_count":0,"update_count":2450}
I20260812 06:19:43.485922 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=2.188937
I20260812 06:19:43.497185 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4247,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.497771 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling MajorDeltaCompactionOp(2facba7b224945e2a0c46626c20af092): perf score=1.000000
I20260812 06:19:43.682770 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: MajorDeltaCompactionOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.185s	user 0.140s	sys 0.044s Metrics: {"cfile_cache_miss":622,"cfile_cache_miss_bytes":28507854,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":856,"lbm_read_time_us":12237,"lbm_reads_lt_1ms":662,"lbm_write_time_us":31028,"lbm_writes_lt_1ms":633,"mutex_wait_us":20,"peak_mem_usage":74091738,"reinsert_count":0,"spinlock_wait_cycles":15744,"update_count":2950}
I20260812 06:19:43.685835 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=14.095187
I20260812 06:19:43.730504 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.043s	user 0.023s	sys 0.020s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":18781,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:43.731619 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=2.188937
I20260812 06:19:43.756821 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.025s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5423,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.757331 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=2.188937
I20260812 06:19:43.767169 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3623,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.767855 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling MajorDeltaCompactionOp(2facba7b224945e2a0c46626c20af092): perf score=1.000000
I20260812 06:19:43.956110 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: MajorDeltaCompactionOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.188s	user 0.140s	sys 0.048s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918213,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":205,"lbm_read_time_us":13572,"lbm_reads_lt_1ms":673,"lbm_write_time_us":30067,"lbm_writes_lt_1ms":643,"mutex_wait_us":48,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":3000}
I20260812 06:19:43.956841 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=14.095187
I20260812 06:19:44.002400 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.045s	user 0.022s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19715,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:44.002990 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling MajorDeltaCompactionOp(2facba7b224945e2a0c46626c20af092): perf score=1.000000
I20260812 06:19:44.149588 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: MajorDeltaCompactionOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.144s	user 0.077s	sys 0.063s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":896,"lbm_read_time_us":8992,"lbm_reads_lt_1ms":463,"lbm_write_time_us":24045,"lbm_writes_lt_1ms":443,"mutex_wait_us":268,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15232,"update_count":2000}
I20260812 06:19:44.150108 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=14.095187
I20260812 06:19:44.194833 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.045s	user 0.017s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17409,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:44.195355 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=2.188937
I20260812 06:19:44.206060 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3900,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.206710 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling MajorDeltaCompactionOp(2facba7b224945e2a0c46626c20af092): perf score=1.000000
I20260812 06:19:44.374301 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: MajorDeltaCompactionOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.167s	user 0.119s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":286,"lbm_read_time_us":9419,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26237,"lbm_writes_lt_1ms":543,"mutex_wait_us":57,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:19:44.374821 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=11.118625
I20260812 06:19:44.410152 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.035s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":15106,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:44.410645 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=2.188937
I20260812 06:19:44.431789 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.021s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4151,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:44.432297 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=2.188937
I20260812 06:19:44.447861 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5680,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.448410 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling MajorDeltaCompactionOp(2facba7b224945e2a0c46626c20af092): perf score=1.000000
I20260812 06:19:44.593112 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: MajorDeltaCompactionOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.144s	user 0.104s	sys 0.038s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815792,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1807,"lbm_read_time_us":8510,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29836,"lbm_writes_lt_1ms":543,"mutex_wait_us":477,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":384,"update_count":2500}
I20260812 06:19:44.593744 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=11.118625
I20260812 06:19:44.627321 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.033s	user 0.022s	sys 0.010s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":14495,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:44.627940 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=2.188937
I20260812 06:19:44.638768 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3797,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:44.639328 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushMRSOp(2facba7b224945e2a0c46626c20af092): perf score=1.000000
I20260812 06:19:44.671046 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushMRSOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.032s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":217,"dirs.run_wall_time_us":1260,"drs_written":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1498,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:44.671703 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling LogGCOp(2facba7b224945e2a0c46626c20af092): free 117302827 bytes of WAL
I20260812 06:19:44.671916 22706 log_reader.cc:385] T 2facba7b224945e2a0c46626c20af092: removed 12 log segments from log reader
I20260812 06:19:44.671959 22706 log.cc:1079] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/2facba7b224945e2a0c46626c20af092/wal-000000028 (ops 133-137)
I20260812 06:19:44.671985 22706 log.cc:1079] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/2facba7b224945e2a0c46626c20af092/wal-000000029 (ops 138-142)
I20260812 06:19:44.672011 22706 log.cc:1079] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/2facba7b224945e2a0c46626c20af092/wal-000000030 (ops 143-146)
I20260812 06:19:44.672043 22706 log.cc:1079] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/2facba7b224945e2a0c46626c20af092/wal-000000031 (ops 147-151)
I20260812 06:19:44.672075 22706 log.cc:1079] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/2facba7b224945e2a0c46626c20af092/wal-000000032 (ops 152-156)
I20260812 06:19:44.672108 22706 log.cc:1079] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/2facba7b224945e2a0c46626c20af092/wal-000000033 (ops 157-160)
I20260812 06:19:44.672140 22706 log.cc:1079] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/2facba7b224945e2a0c46626c20af092/wal-000000034 (ops 161-165)
I20260812 06:19:44.672171 22706 log.cc:1079] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/2facba7b224945e2a0c46626c20af092/wal-000000035 (ops 166-170)
I20260812 06:19:44.672195 22706 log.cc:1079] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/2facba7b224945e2a0c46626c20af092/wal-000000036 (ops 171-175)
I20260812 06:19:44.672210 22706 log.cc:1079] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/2facba7b224945e2a0c46626c20af092/wal-000000037 (ops 176-180)
I20260812 06:19:44.672230 22706 log.cc:1079] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/2facba7b224945e2a0c46626c20af092/wal-000000038 (ops 181-185)
I20260812 06:19:44.672263 22706 log.cc:1079] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/2facba7b224945e2a0c46626c20af092/wal-000000039 (ops 186-190)
I20260812 06:19:44.693641 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: LogGCOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.022s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:19:44.694100 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=3.181125
I20260812 06:19:44.705158 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.011s	user 0.003s	sys 0.006s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":4004,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:44.705600 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=2.188937
I20260812 06:19:44.719524 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.014s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5123,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:44.719982 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling UndoDeltaBlockGCOp(2facba7b224945e2a0c46626c20af092): 482 bytes on disk
I20260812 06:19:44.720546 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: UndoDeltaBlockGCOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":81,"lbm_reads_lt_1ms":4}
I20260812 06:19:44.721220 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling MajorDeltaCompactionOp(2facba7b224945e2a0c46626c20af092): perf score=1.000000
I20260812 06:19:44.863471 22535 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.721s	user 1.612s	sys 0.218s
I20260812 06:19:44.942602 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: MajorDeltaCompactionOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.221s	user 0.152s	sys 0.063s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918310,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":532,"lbm_read_time_us":13060,"lbm_reads_lt_1ms":670,"lbm_write_time_us":34425,"lbm_writes_lt_1ms":643,"mutex_wait_us":42,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":69,"threads_started":1,"update_count":3000}
I20260812 06:19:44.943356 22812 maintenance_manager.cc:419] P d0ce05ba010244d1b54e05f706ccb92d: Scheduling FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092): perf score=10.126437
I20260812 06:19:44.962812 22535 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.099s	user 0.002s	sys 0.000s
I20260812 06:19:44.963414 22535 tablet_server.cc:179] TabletServer@127.22.1.193:0 shutting down...
I20260812 06:19:44.978425 22706 maintenance_manager.cc:643] P d0ce05ba010244d1b54e05f706ccb92d: FlushDeltaMemStoresOp(2facba7b224945e2a0c46626c20af092) complete. Timing: real 0.035s	user 0.032s	sys 0.000s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14316,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:44.978931 22535 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:44.979277 22535 tablet_replica.cc:333] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d: stopping tablet replica
I20260812 06:19:44.979487 22535 raft_consensus.cc:2243] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:44.979704 22535 raft_consensus.cc:2272] T 2facba7b224945e2a0c46626c20af092 P d0ce05ba010244d1b54e05f706ccb92d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:44.994100 22535 tablet_server.cc:196] TabletServer@127.22.1.193:0 shutdown complete.
I20260812 06:19:44.998440 22535 master.cc:562] Master@127.22.1.254:38101 shutting down...
I20260812 06:19:45.001571 22535 raft_consensus.cc:2243] T 00000000000000000000000000000000 P b390c8371d7341269737980c82747703 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:45.001731 22535 raft_consensus.cc:2272] T 00000000000000000000000000000000 P b390c8371d7341269737980c82747703 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:45.001799 22535 tablet_replica.cc:333] T 00000000000000000000000000000000 P b390c8371d7341269737980c82747703: stopping tablet replica
I20260812 06:19:45.013823 22535 master.cc:584] Master@127.22.1.254:38101 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5165 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:45.098340 22535 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.22.1.254:40153
I20260812 06:19:45.098743 22535 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:45.100629 22861 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:45.100646 22860 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:45.100814 22535 server_base.cc:1061] running on GCE node
W20260812 06:19:45.100908 22863 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:45.101123 22535 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:45.101166 22535 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:45.101186 22535 hybrid_clock.cc:648] HybridClock initialized: now 1786515585101185 us; error 0 us; skew 500 ppm
I20260812 06:19:45.101984 22535 webserver.cc:533] Webserver started at http://127.22.1.254:41317/ using document root <none> and password file <none>
I20260812 06:19:45.102131 22535 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:45.102180 22535 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:45.102257 22535 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:45.102638 22535 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/master-0-root/instance:
uuid: "584627de86e243c2b7ba97461cc9b1ae"
format_stamp: "Formatted at 2026-08-12 06:19:45 on dist-test-slave-7lbf"
I20260812 06:19:45.104053 22535 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:45.104887 22871 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:45.105080 22535 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:45.105149 22535 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/master-0-root
uuid: "584627de86e243c2b7ba97461cc9b1ae"
format_stamp: "Formatted at 2026-08-12 06:19:45 on dist-test-slave-7lbf"
I20260812 06:19:45.105216 22535 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:45.114328 22535 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:45.114657 22535 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:45.118479 22535 rpc_server.cc:307] RPC server started. Bound to: 127.22.1.254:40153
I20260812 06:19:45.121702 22957 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.22.1.254:40153 every 8 connection(s)
I20260812 06:19:45.122223 22961 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:45.123956 22961 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 584627de86e243c2b7ba97461cc9b1ae: Bootstrap starting.
I20260812 06:19:45.124701 22961 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 584627de86e243c2b7ba97461cc9b1ae: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:45.125666 22961 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 584627de86e243c2b7ba97461cc9b1ae: No bootstrap required, opened a new log
I20260812 06:19:45.126041 22961 raft_consensus.cc:359] T 00000000000000000000000000000000 P 584627de86e243c2b7ba97461cc9b1ae [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "584627de86e243c2b7ba97461cc9b1ae" member_type: VOTER }
I20260812 06:19:45.126122 22961 raft_consensus.cc:385] T 00000000000000000000000000000000 P 584627de86e243c2b7ba97461cc9b1ae [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:45.126151 22961 raft_consensus.cc:740] T 00000000000000000000000000000000 P 584627de86e243c2b7ba97461cc9b1ae [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 584627de86e243c2b7ba97461cc9b1ae, State: Initialized, Role: FOLLOWER
I20260812 06:19:45.126288 22961 consensus_queue.cc:260] T 00000000000000000000000000000000 P 584627de86e243c2b7ba97461cc9b1ae [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: "584627de86e243c2b7ba97461cc9b1ae" member_type: VOTER }
I20260812 06:19:45.126375 22961 raft_consensus.cc:399] T 00000000000000000000000000000000 P 584627de86e243c2b7ba97461cc9b1ae [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:45.126412 22961 raft_consensus.cc:493] T 00000000000000000000000000000000 P 584627de86e243c2b7ba97461cc9b1ae [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:45.126459 22961 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 584627de86e243c2b7ba97461cc9b1ae [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:45.127104 22961 raft_consensus.cc:515] T 00000000000000000000000000000000 P 584627de86e243c2b7ba97461cc9b1ae [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "584627de86e243c2b7ba97461cc9b1ae" member_type: VOTER }
I20260812 06:19:45.127228 22961 leader_election.cc:304] T 00000000000000000000000000000000 P 584627de86e243c2b7ba97461cc9b1ae [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: 584627de86e243c2b7ba97461cc9b1ae; no voters: 
I20260812 06:19:45.127388 22961 leader_election.cc:290] T 00000000000000000000000000000000 P 584627de86e243c2b7ba97461cc9b1ae [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:45.127481 22968 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 584627de86e243c2b7ba97461cc9b1ae [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:45.127665 22968 raft_consensus.cc:697] T 00000000000000000000000000000000 P 584627de86e243c2b7ba97461cc9b1ae [term 1 LEADER]: Becoming Leader. State: Replica: 584627de86e243c2b7ba97461cc9b1ae, State: Running, Role: LEADER
I20260812 06:19:45.127796 22961 sys_catalog.cc:565] T 00000000000000000000000000000000 P 584627de86e243c2b7ba97461cc9b1ae [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:45.127795 22968 consensus_queue.cc:237] T 00000000000000000000000000000000 P 584627de86e243c2b7ba97461cc9b1ae [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: "584627de86e243c2b7ba97461cc9b1ae" member_type: VOTER }
I20260812 06:19:45.128266 22970 sys_catalog.cc:455] T 00000000000000000000000000000000 P 584627de86e243c2b7ba97461cc9b1ae [sys.catalog]: SysCatalogTable state changed. Reason: New leader 584627de86e243c2b7ba97461cc9b1ae. Latest consensus state: current_term: 1 leader_uuid: "584627de86e243c2b7ba97461cc9b1ae" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "584627de86e243c2b7ba97461cc9b1ae" member_type: VOTER } }
I20260812 06:19:45.128297 22969 sys_catalog.cc:455] T 00000000000000000000000000000000 P 584627de86e243c2b7ba97461cc9b1ae [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "584627de86e243c2b7ba97461cc9b1ae" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "584627de86e243c2b7ba97461cc9b1ae" member_type: VOTER } }
I20260812 06:19:45.128448 22969 sys_catalog.cc:458] T 00000000000000000000000000000000 P 584627de86e243c2b7ba97461cc9b1ae [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:45.128433 22970 sys_catalog.cc:458] T 00000000000000000000000000000000 P 584627de86e243c2b7ba97461cc9b1ae [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:45.128953 22978 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:45.129716 22978 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:45.129873 22535 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:45.131582 22978 catalog_manager.cc:1383] Generated new cluster ID: c1b084bf8bef4d4c875ca0aa7c9834eb
I20260812 06:19:45.131639 22978 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:45.137251 22978 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:45.137802 22978 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:45.161791 22978 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 584627de86e243c2b7ba97461cc9b1ae: Generated new TSK 0
I20260812 06:19:45.162006 22978 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:45.194315 22535 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:45.196218 22996 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:45.196287 22998 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:45.196244 23001 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:45.196534 22535 server_base.cc:1061] running on GCE node
I20260812 06:19:45.196686 22535 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:45.196719 22535 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:45.196733 22535 hybrid_clock.cc:648] HybridClock initialized: now 1786515585196733 us; error 0 us; skew 500 ppm
I20260812 06:19:45.197510 22535 webserver.cc:533] Webserver started at http://127.22.1.193:32963/ using document root <none> and password file <none>
I20260812 06:19:45.197683 22535 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:45.197727 22535 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:45.197784 22535 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:45.198129 22535 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/instance:
uuid: "efb3c3bf57c54fc2ab8047d18cfeb0b3"
format_stamp: "Formatted at 2026-08-12 06:19:45 on dist-test-slave-7lbf"
I20260812 06:19:45.199518 22535 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:45.200348 23007 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:45.200559 22535 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:45.200621 22535 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root
uuid: "efb3c3bf57c54fc2ab8047d18cfeb0b3"
format_stamp: "Formatted at 2026-08-12 06:19:45 on dist-test-slave-7lbf"
I20260812 06:19:45.200677 22535 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:45.208465 22535 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:45.208755 22535 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:45.208997 22535 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:45.209429 22535 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:45.209466 22535 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:45.209509 22535 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:45.209561 22535 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:45.213387 22535 rpc_server.cc:307] RPC server started. Bound to: 127.22.1.193:44899
I20260812 06:19:45.214993 23128 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.22.1.193:44899 every 8 connection(s)
I20260812 06:19:45.222438 23131 heartbeater.cc:344] Connected to a master server at 127.22.1.254:40153
I20260812 06:19:45.222582 23131 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:45.222853 23131 heartbeater.cc:507] Master 127.22.1.254:40153 requested a full tablet report, sending...
I20260812 06:19:45.223567 22897 ts_manager.cc:194] Registered new tserver with Master: efb3c3bf57c54fc2ab8047d18cfeb0b3 (127.22.1.193:44899)
I20260812 06:19:45.223920 22535 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.00980813s
I20260812 06:19:45.224421 22897 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:37888
I20260812 06:19:45.230530 22897 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:37902:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:45.239003 23057 tablet_service.cc:1511] Processing CreateTablet for tablet 515dff7e214145f5aaa9d7e0291b07a5 (DEFAULT_TABLE table=heavy-update-compaction-test [id=7c3ed3de35d04660bf1bde96323c0f43]), partition=
I20260812 06:19:45.239264 23057 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 515dff7e214145f5aaa9d7e0291b07a5. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:45.241194 23156 tablet_bootstrap.cc:492] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Bootstrap starting.
I20260812 06:19:45.242324 23156 tablet_bootstrap.cc:654] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:45.243499 23156 tablet_bootstrap.cc:492] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: No bootstrap required, opened a new log
I20260812 06:19:45.243597 23156 ts_tablet_manager.cc:1403] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:45.244099 23156 raft_consensus.cc:359] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "efb3c3bf57c54fc2ab8047d18cfeb0b3" member_type: VOTER last_known_addr { host: "127.22.1.193" port: 44899 } }
I20260812 06:19:45.244199 23156 raft_consensus.cc:385] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:45.244239 23156 raft_consensus.cc:740] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: efb3c3bf57c54fc2ab8047d18cfeb0b3, State: Initialized, Role: FOLLOWER
I20260812 06:19:45.244400 23156 consensus_queue.cc:260] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3 [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: "efb3c3bf57c54fc2ab8047d18cfeb0b3" member_type: VOTER last_known_addr { host: "127.22.1.193" port: 44899 } }
I20260812 06:19:45.244505 23156 raft_consensus.cc:399] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:45.244555 23156 raft_consensus.cc:493] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:45.244611 23156 raft_consensus.cc:3060] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:45.245440 23156 raft_consensus.cc:515] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "efb3c3bf57c54fc2ab8047d18cfeb0b3" member_type: VOTER last_known_addr { host: "127.22.1.193" port: 44899 } }
I20260812 06:19:45.245607 23156 leader_election.cc:304] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3 [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: efb3c3bf57c54fc2ab8047d18cfeb0b3; no voters: 
I20260812 06:19:45.245807 23156 leader_election.cc:290] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:45.245940 23159 raft_consensus.cc:2804] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:45.246142 23156 ts_tablet_manager.cc:1434] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:45.246150 23159 raft_consensus.cc:697] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3 [term 1 LEADER]: Becoming Leader. State: Replica: efb3c3bf57c54fc2ab8047d18cfeb0b3, State: Running, Role: LEADER
I20260812 06:19:45.246202 23131 heartbeater.cc:499] Master 127.22.1.254:40153 was elected leader, sending a full tablet report...
I20260812 06:19:45.246305 23159 consensus_queue.cc:237] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3 [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: "efb3c3bf57c54fc2ab8047d18cfeb0b3" member_type: VOTER last_known_addr { host: "127.22.1.193" port: 44899 } }
I20260812 06:19:45.247521 22897 catalog_manager.cc:5719] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3 reported cstate change: term changed from 0 to 1, leader changed from <none> to efb3c3bf57c54fc2ab8047d18cfeb0b3 (127.22.1.193). New cstate: current_term: 1 leader_uuid: "efb3c3bf57c54fc2ab8047d18cfeb0b3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "efb3c3bf57c54fc2ab8047d18cfeb0b3" member_type: VOTER last_known_addr { host: "127.22.1.193" port: 44899 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:45.304435 22535 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.049s	user 0.014s	sys 0.008s
I20260812 06:19:45.465452 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushMRSOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=23.023690
I20260812 06:19:45.631796 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushMRSOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.166s	user 0.110s	sys 0.053s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":149,"dirs.run_wall_time_us":909,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42999,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":17792,"update_count":1500}
I20260812 06:19:45.632396 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling LogGCOp(515dff7e214145f5aaa9d7e0291b07a5): free 20743880 bytes of WAL
I20260812 06:19:45.632596 23019 log_reader.cc:385] T 515dff7e214145f5aaa9d7e0291b07a5: removed 2 log segments from log reader
I20260812 06:19:45.632642 23019 log.cc:1079] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/515dff7e214145f5aaa9d7e0291b07a5/wal-000000001 (ops 1-6)
I20260812 06:19:45.632679 23019 log.cc:1079] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/515dff7e214145f5aaa9d7e0291b07a5/wal-000000002 (ops 7-11)
I20260812 06:19:45.636253 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: LogGCOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:45.636636 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling UndoDeltaBlockGCOp(515dff7e214145f5aaa9d7e0291b07a5): 20513818 bytes on disk
I20260812 06:19:45.637059 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: UndoDeltaBlockGCOp(515dff7e214145f5aaa9d7e0291b07a5) 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:19:45.637428 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=2.188937
I20260812 06:19:45.648358 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3930,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.648926 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling MajorDeltaCompactionOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=1.000000
I20260812 06:19:45.792539 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: MajorDeltaCompactionOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.143s	user 0.095s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":43,"lbm_read_time_us":10705,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24133,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18816,"thread_start_us":279,"threads_started":5,"update_count":2000}
I20260812 06:19:45.793186 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=10.126437
I20260812 06:19:45.827245 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.034s	user 0.016s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14591,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:45.827657 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=2.188937
I20260812 06:19:45.847580 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.020s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5169,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.848097 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling MajorDeltaCompactionOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=1.000000
I20260812 06:19:46.000847 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: MajorDeltaCompactionOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.153s	user 0.104s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":166,"lbm_read_time_us":10181,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24136,"lbm_writes_lt_1ms":443,"mutex_wait_us":86,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2000}
I20260812 06:19:46.001468 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=10.126437
I20260812 06:19:46.033505 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.032s	user 0.025s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13852,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:46.034018 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=2.188937
I20260812 06:19:46.047546 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4495,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.048106 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling MajorDeltaCompactionOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=1.000000
I20260812 06:19:46.172942 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: MajorDeltaCompactionOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.125s	user 0.095s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"lbm_read_time_us":9994,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22231,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2000}
I20260812 06:19:46.173393 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=10.126437
I20260812 06:19:46.224113 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.051s	user 0.018s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19726,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:19:46.224645 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=2.188937
I20260812 06:19:46.240269 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5595,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.241125 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling MajorDeltaCompactionOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=1.000000
I20260812 06:19:46.359407 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: MajorDeltaCompactionOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.118s	user 0.089s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":186,"lbm_read_time_us":10607,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20398,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":2000}
I20260812 06:19:46.359961 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=10.126437
I20260812 06:19:46.404155 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.044s	user 0.025s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14848,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:46.404743 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=2.188937
I20260812 06:19:46.415458 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4053,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.415974 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling MajorDeltaCompactionOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=1.000000
I20260812 06:19:46.550496 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: MajorDeltaCompactionOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.134s	user 0.074s	sys 0.060s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":868,"lbm_read_time_us":10427,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20595,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:19:46.551115 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=10.126437
I20260812 06:19:46.586311 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.035s	user 0.022s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14596,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:46.586784 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=2.188937
I20260812 06:19:46.597028 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3856,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.597504 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling MajorDeltaCompactionOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=1.000000
I20260812 06:19:46.713600 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: MajorDeltaCompactionOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.116s	user 0.095s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":192,"lbm_read_time_us":9207,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20969,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":2000}
I20260812 06:19:46.714124 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=10.126437
I20260812 06:19:46.759959 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.046s	user 0.014s	sys 0.029s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21150,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:19:46.760514 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=2.188937
I20260812 06:19:46.770869 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3689,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.771464 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushMRSOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=1.000000
I20260812 06:19:46.804366 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushMRSOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.033s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":297,"dirs.run_wall_time_us":1488,"drs_written":1,"lbm_read_time_us":35,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1314,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:46.805009 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling LogGCOp(515dff7e214145f5aaa9d7e0291b07a5): free 112692363 bytes of WAL
I20260812 06:19:46.805241 23019 log_reader.cc:385] T 515dff7e214145f5aaa9d7e0291b07a5: removed 11 log segments from log reader
I20260812 06:19:46.805302 23019 log.cc:1079] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/515dff7e214145f5aaa9d7e0291b07a5/wal-000000003 (ops 12-16)
I20260812 06:19:46.805336 23019 log.cc:1079] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/515dff7e214145f5aaa9d7e0291b07a5/wal-000000004 (ops 17-21)
I20260812 06:19:46.805372 23019 log.cc:1079] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/515dff7e214145f5aaa9d7e0291b07a5/wal-000000005 (ops 22-26)
I20260812 06:19:46.805410 23019 log.cc:1079] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/515dff7e214145f5aaa9d7e0291b07a5/wal-000000006 (ops 27-31)
I20260812 06:19:46.805449 23019 log.cc:1079] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/515dff7e214145f5aaa9d7e0291b07a5/wal-000000007 (ops 32-36)
I20260812 06:19:46.805486 23019 log.cc:1079] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/515dff7e214145f5aaa9d7e0291b07a5/wal-000000008 (ops 37-41)
I20260812 06:19:46.805542 23019 log.cc:1079] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/515dff7e214145f5aaa9d7e0291b07a5/wal-000000009 (ops 42-46)
I20260812 06:19:46.805581 23019 log.cc:1079] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/515dff7e214145f5aaa9d7e0291b07a5/wal-000000010 (ops 47-51)
I20260812 06:19:46.805619 23019 log.cc:1079] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/515dff7e214145f5aaa9d7e0291b07a5/wal-000000011 (ops 52-56)
I20260812 06:19:46.805655 23019 log.cc:1079] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/515dff7e214145f5aaa9d7e0291b07a5/wal-000000012 (ops 57-61)
I20260812 06:19:46.805692 23019 log.cc:1079] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/515dff7e214145f5aaa9d7e0291b07a5/wal-000000013 (ops 62-66)
I20260812 06:19:46.826387 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: LogGCOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.021s	user 0.000s	sys 0.020s Metrics: {}
I20260812 06:19:46.826812 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=3.181125
I20260812 06:19:46.844602 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.018s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4512901,"delete_count":0,"lbm_write_time_us":5009,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:46.845033 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=2.188937
I20260812 06:19:46.854852 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3386,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:46.855412 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling MajorDeltaCompactionOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=1.000000
I20260812 06:19:47.030618 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: MajorDeltaCompactionOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.175s	user 0.125s	sys 0.048s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918321,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1400,"lbm_read_time_us":11176,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36281,"lbm_writes_lt_1ms":643,"mutex_wait_us":525,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":86,"threads_started":1,"update_count":3000}
I20260812 06:19:47.031152 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling UndoDeltaBlockGCOp(515dff7e214145f5aaa9d7e0291b07a5): 447 bytes on disk
I20260812 06:19:47.031579 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: UndoDeltaBlockGCOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:19:47.032058 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=14.095187
I20260812 06:19:47.071378 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.039s	user 0.021s	sys 0.015s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":16374,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:47.071811 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=2.188937
I20260812 06:19:47.086761 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.015s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5444,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:47.087324 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling MajorDeltaCompactionOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=1.000000
I20260812 06:19:47.238026 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: MajorDeltaCompactionOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.150s	user 0.115s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815681,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1001,"lbm_read_time_us":11473,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26600,"lbm_writes_lt_1ms":543,"mutex_wait_us":346,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8192,"update_count":2500}
I20260812 06:19:47.238538 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=11.118625
I20260812 06:19:47.272588 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.034s	user 0.017s	sys 0.014s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15839,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:19:47.273142 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=2.188937
I20260812 06:19:47.289126 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.016s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5514,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:47.289705 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling MajorDeltaCompactionOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=1.000000
I20260812 06:19:47.428550 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: MajorDeltaCompactionOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.139s	user 0.089s	sys 0.049s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":164,"lbm_read_time_us":10927,"lbm_reads_lt_1ms":464,"lbm_write_time_us":21199,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:47.429792 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=11.118625
I20260812 06:19:47.463388 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.033s	user 0.027s	sys 0.005s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":14103,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:47.463904 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=2.188937
I20260812 06:19:47.478076 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.014s	user 0.004s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4301,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:47.478633 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling MajorDeltaCompactionOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=1.000000
I20260812 06:19:47.607534 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: MajorDeltaCompactionOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.129s	user 0.095s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713264,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":111,"lbm_read_time_us":7179,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23664,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":2000}
I20260812 06:19:47.608165 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=10.126437
I20260812 06:19:47.646338 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.038s	user 0.033s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15433,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:47.646865 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=2.188937
I20260812 06:19:47.656689 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3686,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:47.658933 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling MajorDeltaCompactionOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=1.000000
I20260812 06:19:47.779274 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: MajorDeltaCompactionOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.120s	user 0.081s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":178,"lbm_read_time_us":7933,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21568,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10240,"update_count":2000}
I20260812 06:19:47.779867 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=10.126437
I20260812 06:19:47.814369 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.034s	user 0.022s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15481,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:47.814924 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=2.188937
I20260812 06:19:47.830435 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.015s	user 0.001s	sys 0.014s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5930,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:47.830881 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling MajorDeltaCompactionOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=1.000000
I20260812 06:19:47.942075 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: MajorDeltaCompactionOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.111s	user 0.093s	sys 0.017s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":170,"lbm_read_time_us":7412,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20870,"lbm_writes_lt_1ms":443,"mutex_wait_us":3,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:19:47.942797 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=10.126437
I20260812 06:19:47.986449 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.043s	user 0.023s	sys 0.019s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15352,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:47.987082 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=2.188937
I20260812 06:19:48.000687 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5525,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:48.001235 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling MajorDeltaCompactionOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=1.000000
I20260812 06:19:48.141167 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: MajorDeltaCompactionOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.140s	user 0.112s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713274,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":137,"lbm_read_time_us":10960,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20730,"lbm_writes_lt_1ms":443,"mutex_wait_us":45,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":2000}
I20260812 06:19:48.141848 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=10.126437
I20260812 06:19:48.181108 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.039s	user 0.026s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16378,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:48.181712 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=2.188937
I20260812 06:19:48.191578 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3628,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:48.192106 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushMRSOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=1.000000
I20260812 06:19:48.225838 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushMRSOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.034s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":52,"dirs.run_cpu_time_us":221,"dirs.run_wall_time_us":1274,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1600,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:48.226580 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling LogGCOp(515dff7e214145f5aaa9d7e0291b07a5): free 133024372 bytes of WAL
I20260812 06:19:48.226823 23019 log_reader.cc:385] T 515dff7e214145f5aaa9d7e0291b07a5: removed 13 log segments from log reader
I20260812 06:19:48.226873 23019 log.cc:1079] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/515dff7e214145f5aaa9d7e0291b07a5/wal-000000014 (ops 67-71)
I20260812 06:19:48.226909 23019 log.cc:1079] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/515dff7e214145f5aaa9d7e0291b07a5/wal-000000015 (ops 72-76)
I20260812 06:19:48.226934 23019 log.cc:1079] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/515dff7e214145f5aaa9d7e0291b07a5/wal-000000016 (ops 77-81)
I20260812 06:19:48.226958 23019 log.cc:1079] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/515dff7e214145f5aaa9d7e0291b07a5/wal-000000017 (ops 82-86)
I20260812 06:19:48.226989 23019 log.cc:1079] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/515dff7e214145f5aaa9d7e0291b07a5/wal-000000018 (ops 87-91)
I20260812 06:19:48.227020 23019 log.cc:1079] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/515dff7e214145f5aaa9d7e0291b07a5/wal-000000019 (ops 92-96)
I20260812 06:19:48.227047 23019 log.cc:1079] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/515dff7e214145f5aaa9d7e0291b07a5/wal-000000020 (ops 97-100)
I20260812 06:19:48.227078 23019 log.cc:1079] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/515dff7e214145f5aaa9d7e0291b07a5/wal-000000021 (ops 101-105)
I20260812 06:19:48.227108 23019 log.cc:1079] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/515dff7e214145f5aaa9d7e0291b07a5/wal-000000022 (ops 106-110)
I20260812 06:19:48.227138 23019 log.cc:1079] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/515dff7e214145f5aaa9d7e0291b07a5/wal-000000023 (ops 111-115)
I20260812 06:19:48.227167 23019 log.cc:1079] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/515dff7e214145f5aaa9d7e0291b07a5/wal-000000024 (ops 116-120)
I20260812 06:19:48.227198 23019 log.cc:1079] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/515dff7e214145f5aaa9d7e0291b07a5/wal-000000025 (ops 121-125)
I20260812 06:19:48.227226 23019 log.cc:1079] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/515dff7e214145f5aaa9d7e0291b07a5/wal-000000026 (ops 126-130)
I20260812 06:19:48.251765 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: LogGCOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.025s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:19:48.252331 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=3.181125
I20260812 06:19:48.276544 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.024s	user 0.018s	sys 0.000s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":4378,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:48.277040 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=2.188937
I20260812 06:19:48.290802 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5196,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:48.291322 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling UndoDeltaBlockGCOp(515dff7e214145f5aaa9d7e0291b07a5): 483 bytes on disk
I20260812 06:19:48.291821 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: UndoDeltaBlockGCOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:19:48.292325 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling MajorDeltaCompactionOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=1.000000
I20260812 06:19:48.482475 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: MajorDeltaCompactionOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.190s	user 0.126s	sys 0.063s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918320,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":739,"lbm_read_time_us":13464,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32748,"lbm_writes_lt_1ms":643,"mutex_wait_us":59,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6912,"thread_start_us":80,"threads_started":1,"update_count":3000}
I20260812 06:19:48.483031 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=14.095187
I20260812 06:19:48.544361 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.061s	user 0.035s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20418,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:48.544936 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=2.188937
I20260812 06:19:48.559995 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5668,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:48.561383 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling MajorDeltaCompactionOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=1.000000
I20260812 06:19:48.740085 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: MajorDeltaCompactionOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.178s	user 0.119s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":606,"lbm_read_time_us":12442,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26982,"lbm_writes_lt_1ms":543,"mutex_wait_us":63,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:48.740605 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=14.095187
I20260812 06:19:48.791499 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.051s	user 0.026s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18930,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:48.792181 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=2.188937
I20260812 06:19:48.816653 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.024s	user 0.011s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6028,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:48.817276 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling MajorDeltaCompactionOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=1.000000
I20260812 06:19:48.998867 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: MajorDeltaCompactionOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.181s	user 0.113s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":125,"lbm_read_time_us":12154,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27318,"lbm_writes_lt_1ms":543,"mutex_wait_us":19,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2500}
I20260812 06:19:48.999480 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=14.095187
I20260812 06:19:49.045951 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.046s	user 0.023s	sys 0.017s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":17693,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:49.046461 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=2.188937
I20260812 06:19:49.062969 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.016s	user 0.009s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6227,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.063542 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling MajorDeltaCompactionOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=1.000000
I20260812 06:19:49.233234 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: MajorDeltaCompactionOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.170s	user 0.123s	sys 0.034s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":599,"lbm_read_time_us":9060,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26470,"lbm_writes_lt_1ms":543,"mutex_wait_us":273,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:49.233786 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=14.095187
I20260812 06:19:49.286186 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.052s	user 0.032s	sys 0.018s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22687,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:49.286633 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=2.188937
I20260812 06:19:49.301956 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5748,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.302556 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling MajorDeltaCompactionOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=1.000000
I20260812 06:19:49.449918 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: MajorDeltaCompactionOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.147s	user 0.101s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":340,"lbm_read_time_us":10954,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29251,"lbm_writes_lt_1ms":543,"mutex_wait_us":31,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2500}
I20260812 06:19:49.450541 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=11.118625
I20260812 06:19:49.489758 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.039s	user 0.022s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16989,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:19:49.490202 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=2.188937
I20260812 06:19:49.509049 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.019s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4168,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.509589 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=2.188937
I20260812 06:19:49.523353 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.014s	user 0.010s	sys 0.002s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4836,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:49.523888 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling MajorDeltaCompactionOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=1.000000
I20260812 06:19:49.663062 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: MajorDeltaCompactionOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.139s	user 0.095s	sys 0.043s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1262,"lbm_read_time_us":8995,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28081,"lbm_writes_lt_1ms":543,"mutex_wait_us":448,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2500}
I20260812 06:19:49.663681 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=10.126437
I20260812 06:19:49.700942 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.037s	user 0.029s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15872,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:49.701459 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=2.188937
I20260812 06:19:49.715030 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.013s	user 0.010s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4922,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.715529 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushMRSOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=1.000000
I20260812 06:19:49.748404 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushMRSOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.033s	user 0.030s	sys 0.001s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":174,"dirs.run_wall_time_us":1467,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1520,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:49.749085 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling LogGCOp(515dff7e214145f5aaa9d7e0291b07a5): free 124257501 bytes of WAL
I20260812 06:19:49.749328 23019 log_reader.cc:385] T 515dff7e214145f5aaa9d7e0291b07a5: removed 12 log segments from log reader
I20260812 06:19:49.749375 23019 log.cc:1079] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/515dff7e214145f5aaa9d7e0291b07a5/wal-000000027 (ops 131-135)
I20260812 06:19:49.749403 23019 log.cc:1079] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/515dff7e214145f5aaa9d7e0291b07a5/wal-000000028 (ops 136-140)
I20260812 06:19:49.749433 23019 log.cc:1079] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/515dff7e214145f5aaa9d7e0291b07a5/wal-000000029 (ops 141-145)
I20260812 06:19:49.749536 23019 log.cc:1079] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/515dff7e214145f5aaa9d7e0291b07a5/wal-000000030 (ops 146-150)
I20260812 06:19:49.749576 23019 log.cc:1079] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/515dff7e214145f5aaa9d7e0291b07a5/wal-000000031 (ops 151-154)
I20260812 06:19:49.749601 23019 log.cc:1079] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/515dff7e214145f5aaa9d7e0291b07a5/wal-000000032 (ops 155-159)
I20260812 06:19:49.749657 23019 log.cc:1079] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/515dff7e214145f5aaa9d7e0291b07a5/wal-000000033 (ops 160-164)
I20260812 06:19:49.749704 23019 log.cc:1079] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/515dff7e214145f5aaa9d7e0291b07a5/wal-000000034 (ops 165-169)
I20260812 06:19:49.749748 23019 log.cc:1079] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/515dff7e214145f5aaa9d7e0291b07a5/wal-000000035 (ops 170-174)
I20260812 06:19:49.749789 23019 log.cc:1079] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/515dff7e214145f5aaa9d7e0291b07a5/wal-000000036 (ops 175-179)
I20260812 06:19:49.749836 23019 log.cc:1079] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/515dff7e214145f5aaa9d7e0291b07a5/wal-000000037 (ops 180-184)
I20260812 06:19:49.749886 23019 log.cc:1079] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/515dff7e214145f5aaa9d7e0291b07a5/wal-000000038 (ops 185-189)
I20260812 06:19:49.771832 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: LogGCOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.023s	user 0.001s	sys 0.019s Metrics: {}
I20260812 06:19:49.772482 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=4.173312
I20260812 06:19:49.786121 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":5784657,"delete_count":0,"lbm_write_time_us":5365,"lbm_writes_lt_1ms":144,"reinsert_count":0,"update_count":705}
I20260812 06:19:49.786551 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling LogGCOp(515dff7e214145f5aaa9d7e0291b07a5): free 8767145 bytes of WAL
I20260812 06:19:49.786772 23019 log_reader.cc:385] T 515dff7e214145f5aaa9d7e0291b07a5: removed 1 log segments from log reader
I20260812 06:19:49.786844 23019 log.cc:1079] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: Deleting log segment in path: /tmp/dist-test-task8osgJw/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579911049-22535-0/minicluster-data/ts-0-root/wals/515dff7e214145f5aaa9d7e0291b07a5/wal-000000039 (ops 190-194)
I20260812 06:19:49.788683 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: LogGCOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:49.788978 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling UndoDeltaBlockGCOp(515dff7e214145f5aaa9d7e0291b07a5): 492 bytes on disk
I20260812 06:19:49.789371 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: UndoDeltaBlockGCOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:19:49.789877 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=1.196750
I20260812 06:19:49.805200 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.015s	user 0.008s	sys 0.000s Metrics: {"bytes_written":2420629,"delete_count":0,"lbm_write_time_us":3434,"lbm_writes_lt_1ms":62,"reinsert_count":0,"update_count":295}
I20260812 06:19:49.805706 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling MajorDeltaCompactionOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=1.000000
I20260812 06:19:49.908133 22535 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.604s	user 1.722s	sys 0.109s
I20260812 06:19:49.969381 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: MajorDeltaCompactionOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.164s	user 0.120s	sys 0.041s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918296,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2908,"lbm_read_time_us":10189,"lbm_reads_lt_1ms":662,"lbm_write_time_us":34896,"lbm_writes_lt_1ms":643,"mutex_wait_us":295,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10112,"thread_start_us":85,"threads_started":1,"update_count":3000}
I20260812 06:19:49.970016 23132 maintenance_manager.cc:419] P efb3c3bf57c54fc2ab8047d18cfeb0b3: Scheduling FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5): perf score=10.126437
I20260812 06:19:49.982918 22535 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.074s	user 0.002s	sys 0.000s
I20260812 06:19:49.983397 22535 tablet_server.cc:179] TabletServer@127.22.1.193:0 shutting down...
I20260812 06:19:50.001713 23019 maintenance_manager.cc:643] P efb3c3bf57c54fc2ab8047d18cfeb0b3: FlushDeltaMemStoresOp(515dff7e214145f5aaa9d7e0291b07a5) complete. Timing: real 0.032s	user 0.025s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13750,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:50.002239 22535 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:50.002449 22535 tablet_replica.cc:333] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3: stopping tablet replica
I20260812 06:19:50.002583 22535 raft_consensus.cc:2243] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:50.002740 22535 raft_consensus.cc:2272] T 515dff7e214145f5aaa9d7e0291b07a5 P efb3c3bf57c54fc2ab8047d18cfeb0b3 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:50.005743 22535 tablet_server.cc:196] TabletServer@127.22.1.193:0 shutdown complete.
I20260812 06:19:50.016044 22535 master.cc:562] Master@127.22.1.254:40153 shutting down...
I20260812 06:19:50.018944 22535 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 584627de86e243c2b7ba97461cc9b1ae [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:50.019115 22535 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 584627de86e243c2b7ba97461cc9b1ae [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:50.019181 22535 tablet_replica.cc:333] T 00000000000000000000000000000000 P 584627de86e243c2b7ba97461cc9b1ae: stopping tablet replica
I20260812 06:19:50.031164 22535 master.cc:584] Master@127.22.1.254:40153 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5015 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10182 ms total)

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