[==========] 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:54.195217 25119 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.24.135.254:44209
I20260812 06:19:54.196388 25119 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:54.197016 25119 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:54.203608 25130 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:54.203644 25119 server_base.cc:1061] running on GCE node
W20260812 06:19:54.203622 25132 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:54.203603 25129 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:54.204396 25119 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:54.204517 25119 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:54.204589 25119 hybrid_clock.cc:648] HybridClock initialized: now 1786515594204587 us; error 0 us; skew 500 ppm
I20260812 06:19:54.206372 25119 webserver.cc:533] Webserver started at http://127.24.135.254:34535/ using document root <none> and password file <none>
I20260812 06:19:54.206911 25119 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:54.206969 25119 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:54.207206 25119 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:54.209003 25119 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/master-0-root/instance:
uuid: "f12ffaf6cfcb40c789525f411b296dcb"
format_stamp: "Formatted at 2026-08-12 06:19:54 on dist-test-slave-04bb"
I20260812 06:19:54.212307 25119 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:54.214303 25139 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:54.215220 25119 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:54.215312 25119 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/master-0-root
uuid: "f12ffaf6cfcb40c789525f411b296dcb"
format_stamp: "Formatted at 2026-08-12 06:19:54 on dist-test-slave-04bb"
I20260812 06:19:54.215428 25119 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-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:54.223699 25119 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:54.224220 25119 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:54.224378 25119 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:54.231554 25119 rpc_server.cc:307] RPC server started. Bound to: 127.24.135.254:44209
I20260812 06:19:54.231609 25234 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.135.254:44209 every 8 connection(s)
I20260812 06:19:54.233834 25237 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:54.239106 25237 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f12ffaf6cfcb40c789525f411b296dcb: Bootstrap starting.
I20260812 06:19:54.241477 25237 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P f12ffaf6cfcb40c789525f411b296dcb: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:54.242362 25237 log.cc:826] T 00000000000000000000000000000000 P f12ffaf6cfcb40c789525f411b296dcb: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:54.244333 25237 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f12ffaf6cfcb40c789525f411b296dcb: No bootstrap required, opened a new log
I20260812 06:19:54.247073 25237 raft_consensus.cc:359] T 00000000000000000000000000000000 P f12ffaf6cfcb40c789525f411b296dcb [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f12ffaf6cfcb40c789525f411b296dcb" member_type: VOTER }
I20260812 06:19:54.247272 25237 raft_consensus.cc:385] T 00000000000000000000000000000000 P f12ffaf6cfcb40c789525f411b296dcb [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:54.247367 25237 raft_consensus.cc:740] T 00000000000000000000000000000000 P f12ffaf6cfcb40c789525f411b296dcb [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f12ffaf6cfcb40c789525f411b296dcb, State: Initialized, Role: FOLLOWER
I20260812 06:19:54.247956 25237 consensus_queue.cc:260] T 00000000000000000000000000000000 P f12ffaf6cfcb40c789525f411b296dcb [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: "f12ffaf6cfcb40c789525f411b296dcb" member_type: VOTER }
I20260812 06:19:54.248136 25237 raft_consensus.cc:399] T 00000000000000000000000000000000 P f12ffaf6cfcb40c789525f411b296dcb [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:54.248221 25237 raft_consensus.cc:493] T 00000000000000000000000000000000 P f12ffaf6cfcb40c789525f411b296dcb [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:54.248366 25237 raft_consensus.cc:3060] T 00000000000000000000000000000000 P f12ffaf6cfcb40c789525f411b296dcb [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:54.249173 25237 raft_consensus.cc:515] T 00000000000000000000000000000000 P f12ffaf6cfcb40c789525f411b296dcb [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f12ffaf6cfcb40c789525f411b296dcb" member_type: VOTER }
I20260812 06:19:54.249609 25237 leader_election.cc:304] T 00000000000000000000000000000000 P f12ffaf6cfcb40c789525f411b296dcb [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: f12ffaf6cfcb40c789525f411b296dcb; no voters: 
I20260812 06:19:54.249944 25237 leader_election.cc:290] T 00000000000000000000000000000000 P f12ffaf6cfcb40c789525f411b296dcb [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:54.250063 25242 raft_consensus.cc:2804] T 00000000000000000000000000000000 P f12ffaf6cfcb40c789525f411b296dcb [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:54.250345 25242 raft_consensus.cc:697] T 00000000000000000000000000000000 P f12ffaf6cfcb40c789525f411b296dcb [term 1 LEADER]: Becoming Leader. State: Replica: f12ffaf6cfcb40c789525f411b296dcb, State: Running, Role: LEADER
I20260812 06:19:54.250793 25242 consensus_queue.cc:237] T 00000000000000000000000000000000 P f12ffaf6cfcb40c789525f411b296dcb [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: "f12ffaf6cfcb40c789525f411b296dcb" member_type: VOTER }
I20260812 06:19:54.250890 25237 sys_catalog.cc:565] T 00000000000000000000000000000000 P f12ffaf6cfcb40c789525f411b296dcb [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:54.252465 25244 sys_catalog.cc:455] T 00000000000000000000000000000000 P f12ffaf6cfcb40c789525f411b296dcb [sys.catalog]: SysCatalogTable state changed. Reason: New leader f12ffaf6cfcb40c789525f411b296dcb. Latest consensus state: current_term: 1 leader_uuid: "f12ffaf6cfcb40c789525f411b296dcb" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f12ffaf6cfcb40c789525f411b296dcb" member_type: VOTER } }
I20260812 06:19:54.252516 25243 sys_catalog.cc:455] T 00000000000000000000000000000000 P f12ffaf6cfcb40c789525f411b296dcb [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "f12ffaf6cfcb40c789525f411b296dcb" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f12ffaf6cfcb40c789525f411b296dcb" member_type: VOTER } }
I20260812 06:19:54.252617 25244 sys_catalog.cc:458] T 00000000000000000000000000000000 P f12ffaf6cfcb40c789525f411b296dcb [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:54.252631 25243 sys_catalog.cc:458] T 00000000000000000000000000000000 P f12ffaf6cfcb40c789525f411b296dcb [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:54.253010 25255 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:54.255131 25255 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:54.255396 25119 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:54.259594 25255 catalog_manager.cc:1383] Generated new cluster ID: 3876094f957b4b558f671202c3fc6f2e
I20260812 06:19:54.259657 25255 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:54.275338 25255 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:54.276153 25255 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:54.286367 25255 catalog_manager.cc:6092] T 00000000000000000000000000000000 P f12ffaf6cfcb40c789525f411b296dcb: Generated new TSK 0
I20260812 06:19:54.286962 25255 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:54.320183 25119 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:54.323150 25272 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:54.323266 25275 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:54.323266 25273 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:54.323480 25119 server_base.cc:1061] running on GCE node
I20260812 06:19:54.323704 25119 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:54.323757 25119 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:54.323779 25119 hybrid_clock.cc:648] HybridClock initialized: now 1786515594323779 us; error 0 us; skew 500 ppm
I20260812 06:19:54.324743 25119 webserver.cc:533] Webserver started at http://127.24.135.193:32793/ using document root <none> and password file <none>
I20260812 06:19:54.324911 25119 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:54.324967 25119 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:54.325043 25119 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:54.325471 25119 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root/instance:
uuid: "8f0a23ceaf1e42d39e09aedea9fcd0ee"
format_stamp: "Formatted at 2026-08-12 06:19:54 on dist-test-slave-04bb"
I20260812 06:19:54.327244 25119 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:54.328326 25287 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:54.328647 25119 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:54.328717 25119 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root
uuid: "8f0a23ceaf1e42d39e09aedea9fcd0ee"
format_stamp: "Formatted at 2026-08-12 06:19:54 on dist-test-slave-04bb"
I20260812 06:19:54.328806 25119 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-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:54.352090 25119 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:54.352516 25119 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:54.353049 25119 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:54.353912 25119 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:54.353987 25119 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:54.354054 25119 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:54.354104 25119 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:54.360632 25119 rpc_server.cc:307] RPC server started. Bound to: 127.24.135.193:36197
I20260812 06:19:54.360692 25384 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.135.193:36197 every 8 connection(s)
I20260812 06:19:54.369953 25385 heartbeater.cc:344] Connected to a master server at 127.24.135.254:44209
I20260812 06:19:54.370194 25385 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:54.370572 25385 heartbeater.cc:507] Master 127.24.135.254:44209 requested a full tablet report, sending...
I20260812 06:19:54.371871 25165 ts_manager.cc:194] Registered new tserver with Master: 8f0a23ceaf1e42d39e09aedea9fcd0ee (127.24.135.193:36197)
I20260812 06:19:54.372509 25119 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011251794s
I20260812 06:19:54.373395 25165 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:59644
I20260812 06:19:54.382709 25165 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:59652:
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:54.395726 25332 tablet_service.cc:1511] Processing CreateTablet for tablet aa38b0cef33b4ff29604d801ee712484 (DEFAULT_TABLE table=heavy-update-compaction-test [id=b1b6204bf7024f38a679812ba1ab74a1]), partition=
I20260812 06:19:54.396242 25332 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet aa38b0cef33b4ff29604d801ee712484. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:54.398453 25404 tablet_bootstrap.cc:492] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Bootstrap starting.
I20260812 06:19:54.399693 25404 tablet_bootstrap.cc:654] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:54.400875 25404 tablet_bootstrap.cc:492] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: No bootstrap required, opened a new log
I20260812 06:19:54.400956 25404 ts_tablet_manager.cc:1403] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:54.401387 25404 raft_consensus.cc:359] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8f0a23ceaf1e42d39e09aedea9fcd0ee" member_type: VOTER last_known_addr { host: "127.24.135.193" port: 36197 } }
I20260812 06:19:54.401482 25404 raft_consensus.cc:385] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:54.401505 25404 raft_consensus.cc:740] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8f0a23ceaf1e42d39e09aedea9fcd0ee, State: Initialized, Role: FOLLOWER
I20260812 06:19:54.401669 25404 consensus_queue.cc:260] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee [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: "8f0a23ceaf1e42d39e09aedea9fcd0ee" member_type: VOTER last_known_addr { host: "127.24.135.193" port: 36197 } }
I20260812 06:19:54.401741 25404 raft_consensus.cc:399] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:54.401767 25404 raft_consensus.cc:493] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:54.401844 25404 raft_consensus.cc:3060] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:54.402644 25404 raft_consensus.cc:515] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8f0a23ceaf1e42d39e09aedea9fcd0ee" member_type: VOTER last_known_addr { host: "127.24.135.193" port: 36197 } }
I20260812 06:19:54.402828 25404 leader_election.cc:304] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee [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: 8f0a23ceaf1e42d39e09aedea9fcd0ee; no voters: 
I20260812 06:19:54.403056 25404 leader_election.cc:290] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:54.403407 25404 ts_tablet_manager.cc:1434] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:54.403859 25385 heartbeater.cc:499] Master 127.24.135.254:44209 was elected leader, sending a full tablet report...
I20260812 06:19:54.404115 25407 raft_consensus.cc:2804] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:54.404320 25407 raft_consensus.cc:697] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee [term 1 LEADER]: Becoming Leader. State: Replica: 8f0a23ceaf1e42d39e09aedea9fcd0ee, State: Running, Role: LEADER
I20260812 06:19:54.404450 25407 consensus_queue.cc:237] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee [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: "8f0a23ceaf1e42d39e09aedea9fcd0ee" member_type: VOTER last_known_addr { host: "127.24.135.193" port: 36197 } }
I20260812 06:19:54.407822 25165 catalog_manager.cc:5719] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee reported cstate change: term changed from 0 to 1, leader changed from <none> to 8f0a23ceaf1e42d39e09aedea9fcd0ee (127.24.135.193). New cstate: current_term: 1 leader_uuid: "8f0a23ceaf1e42d39e09aedea9fcd0ee" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8f0a23ceaf1e42d39e09aedea9fcd0ee" member_type: VOTER last_known_addr { host: "127.24.135.193" port: 36197 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:54.469480 25119 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.019s	sys 0.004s
I20260812 06:19:54.611949 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushMRSOp(aa38b0cef33b4ff29604d801ee712484): perf score=19.054940
I20260812 06:19:54.782346 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushMRSOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.170s	user 0.132s	sys 0.028s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":219,"delete_count":0,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":213,"dirs.run_wall_time_us":824,"drs_written":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43944,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":137,"threads_started":1,"update_count":1500}
I20260812 06:19:54.783468 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling LogGCOp(aa38b0cef33b4ff29604d801ee712484): free 20743880 bytes of WAL
I20260812 06:19:54.783797 25292 log_reader.cc:385] T aa38b0cef33b4ff29604d801ee712484: removed 2 log segments from log reader
I20260812 06:19:54.783896 25292 log.cc:1079] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/aa38b0cef33b4ff29604d801ee712484/wal-000000001 (ops 1-6)
I20260812 06:19:54.784009 25292 log.cc:1079] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/aa38b0cef33b4ff29604d801ee712484/wal-000000002 (ops 7-11)
I20260812 06:19:54.788671 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: LogGCOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.005s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:19:54.788997 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling UndoDeltaBlockGCOp(aa38b0cef33b4ff29604d801ee712484): 16411393 bytes on disk
I20260812 06:19:54.789572 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: UndoDeltaBlockGCOp(aa38b0cef33b4ff29604d801ee712484) 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:54.790066 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=2.188937
I20260812 06:19:54.811497 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.021s	user 0.012s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6471,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:54.811964 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling MajorDeltaCompactionOp(aa38b0cef33b4ff29604d801ee712484): perf score=1.000000
I20260812 06:19:54.971529 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: MajorDeltaCompactionOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.159s	user 0.106s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":545,"lbm_read_time_us":9628,"lbm_reads_lt_1ms":460,"lbm_write_time_us":26156,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":301,"threads_started":5,"update_count":2000}
I20260812 06:19:54.972061 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=10.126437
I20260812 06:19:55.016074 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.044s	user 0.033s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":20602,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:55.016636 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=2.188937
I20260812 06:19:55.031666 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5736,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.032226 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling MajorDeltaCompactionOp(aa38b0cef33b4ff29604d801ee712484): perf score=1.000000
I20260812 06:19:55.158237 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: MajorDeltaCompactionOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.126s	user 0.110s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":233,"lbm_read_time_us":9255,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26131,"lbm_writes_lt_1ms":443,"mutex_wait_us":53,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7552,"update_count":2000}
I20260812 06:19:55.158828 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=10.126437
I20260812 06:19:55.203011 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.044s	user 0.033s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19237,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:55.203480 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=2.188937
I20260812 06:19:55.214830 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4298,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.215348 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling MajorDeltaCompactionOp(aa38b0cef33b4ff29604d801ee712484): perf score=1.000000
I20260812 06:19:55.350766 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: MajorDeltaCompactionOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.135s	user 0.099s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":254,"lbm_read_time_us":11154,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26934,"lbm_writes_lt_1ms":443,"mutex_wait_us":54,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":30336,"update_count":2000}
I20260812 06:19:55.351336 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=10.126437
I20260812 06:19:55.401690 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.050s	user 0.025s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15384,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:55.402192 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=2.188937
I20260812 06:19:55.418810 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.016s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6323,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.419368 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling MajorDeltaCompactionOp(aa38b0cef33b4ff29604d801ee712484): perf score=1.000000
I20260812 06:19:55.578090 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: MajorDeltaCompactionOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.159s	user 0.118s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1255,"lbm_read_time_us":12331,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26277,"lbm_writes_lt_1ms":443,"mutex_wait_us":373,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2000}
I20260812 06:19:55.578701 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=10.126437
I20260812 06:19:55.629840 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.051s	user 0.019s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19070,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:19:55.630441 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=2.188937
I20260812 06:19:55.642848 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4601,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.643452 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling MajorDeltaCompactionOp(aa38b0cef33b4ff29604d801ee712484): perf score=1.000000
I20260812 06:19:55.787734 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: MajorDeltaCompactionOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.144s	user 0.101s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":187,"lbm_read_time_us":8426,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27378,"lbm_writes_lt_1ms":443,"mutex_wait_us":62,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7296,"update_count":2000}
I20260812 06:19:55.788349 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=14.095187
I20260812 06:19:55.840099 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.052s	user 0.035s	sys 0.004s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18695,"lbm_writes_lt_1ms":403,"mutex_wait_us":18,"reinsert_count":0,"update_count":2000}
I20260812 06:19:55.840735 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=2.188937
I20260812 06:19:55.851634 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.011s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4127,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.852207 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling MajorDeltaCompactionOp(aa38b0cef33b4ff29604d801ee712484): perf score=1.000000
I20260812 06:19:56.004436 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: MajorDeltaCompactionOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.151s	user 0.129s	sys 0.020s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":600,"lbm_read_time_us":11027,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30760,"lbm_writes_lt_1ms":543,"mutex_wait_us":231,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":23552,"update_count":2500}
I20260812 06:19:56.005276 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=11.118625
I20260812 06:19:56.041986 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.036s	user 0.031s	sys 0.003s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15394,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:56.042579 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=2.188937
I20260812 06:19:56.057034 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.014s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5606,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:56.057471 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushMRSOp(aa38b0cef33b4ff29604d801ee712484): perf score=1.000000
I20260812 06:19:56.086895 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushMRSOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.029s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":200,"dirs.run_wall_time_us":1270,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1402,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:56.087656 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling LogGCOp(aa38b0cef33b4ff29604d801ee712484): free 112692367 bytes of WAL
I20260812 06:19:56.087888 25292 log_reader.cc:385] T aa38b0cef33b4ff29604d801ee712484: removed 11 log segments from log reader
I20260812 06:19:56.087932 25292 log.cc:1079] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/aa38b0cef33b4ff29604d801ee712484/wal-000000003 (ops 12-16)
I20260812 06:19:56.087961 25292 log.cc:1079] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/aa38b0cef33b4ff29604d801ee712484/wal-000000004 (ops 17-21)
I20260812 06:19:56.088001 25292 log.cc:1079] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/aa38b0cef33b4ff29604d801ee712484/wal-000000005 (ops 22-26)
I20260812 06:19:56.088048 25292 log.cc:1079] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/aa38b0cef33b4ff29604d801ee712484/wal-000000006 (ops 27-31)
I20260812 06:19:56.088111 25292 log.cc:1079] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/aa38b0cef33b4ff29604d801ee712484/wal-000000007 (ops 32-36)
I20260812 06:19:56.088155 25292 log.cc:1079] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/aa38b0cef33b4ff29604d801ee712484/wal-000000008 (ops 37-41)
I20260812 06:19:56.088174 25292 log.cc:1079] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/aa38b0cef33b4ff29604d801ee712484/wal-000000009 (ops 42-46)
I20260812 06:19:56.088213 25292 log.cc:1079] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/aa38b0cef33b4ff29604d801ee712484/wal-000000010 (ops 47-51)
I20260812 06:19:56.088251 25292 log.cc:1079] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/aa38b0cef33b4ff29604d801ee712484/wal-000000011 (ops 52-56)
I20260812 06:19:56.088307 25292 log.cc:1079] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/aa38b0cef33b4ff29604d801ee712484/wal-000000012 (ops 57-61)
I20260812 06:19:56.088347 25292 log.cc:1079] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/aa38b0cef33b4ff29604d801ee712484/wal-000000013 (ops 62-66)
I20260812 06:19:56.117427 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: LogGCOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.030s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:19:56.118089 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling UndoDeltaBlockGCOp(aa38b0cef33b4ff29604d801ee712484): 472 bytes on disk
I20260812 06:19:56.118672 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: UndoDeltaBlockGCOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:19:56.119194 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=4.173312
I20260812 06:19:56.133978 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.015s	user 0.004s	sys 0.009s Metrics: {"bytes_written":5784657,"delete_count":0,"lbm_write_time_us":6176,"lbm_writes_lt_1ms":144,"reinsert_count":0,"update_count":705}
I20260812 06:19:56.134375 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling LogGCOp(aa38b0cef33b4ff29604d801ee712484): free 12017927 bytes of WAL
I20260812 06:19:56.134563 25292 log_reader.cc:385] T aa38b0cef33b4ff29604d801ee712484: removed 1 log segments from log reader
I20260812 06:19:56.134606 25292 log.cc:1079] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/aa38b0cef33b4ff29604d801ee712484/wal-000000014 (ops 67-71)
I20260812 06:19:56.137034 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: LogGCOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:56.137323 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=1.196750
I20260812 06:19:56.152455 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.015s	user 0.005s	sys 0.005s Metrics: {"bytes_written":2420629,"delete_count":0,"lbm_write_time_us":3855,"lbm_writes_lt_1ms":62,"reinsert_count":0,"update_count":295}
I20260812 06:19:56.152989 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling MajorDeltaCompactionOp(aa38b0cef33b4ff29604d801ee712484): perf score=1.000000
I20260812 06:19:56.320796 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: MajorDeltaCompactionOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.168s	user 0.133s	sys 0.034s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877293,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":514,"lbm_read_time_us":11466,"lbm_reads_lt_1ms":666,"lbm_write_time_us":36690,"lbm_writes_lt_1ms":643,"mutex_wait_us":1,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":103,"threads_started":1,"update_count":3000}
I20260812 06:19:56.321477 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=14.095187
I20260812 06:19:56.376794 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.055s	user 0.034s	sys 0.020s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":23165,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:56.377344 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=3.181125
I20260812 06:19:56.397501 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.020s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":5220,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:56.397914 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=2.188937
I20260812 06:19:56.407438 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.009s	user 0.003s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3717,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:56.407829 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling MajorDeltaCompactionOp(aa38b0cef33b4ff29604d801ee712484): perf score=1.000000
I20260812 06:19:56.580550 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: MajorDeltaCompactionOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.173s	user 0.131s	sys 0.040s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877209,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":333,"lbm_read_time_us":13578,"lbm_reads_lt_1ms":673,"lbm_write_time_us":38584,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":3000}
I20260812 06:19:56.581157 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=14.095187
I20260812 06:19:56.639315 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.058s	user 0.033s	sys 0.019s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":24965,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:56.639802 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=2.188937
I20260812 06:19:56.651206 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4079,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:56.651747 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling MajorDeltaCompactionOp(aa38b0cef33b4ff29604d801ee712484): perf score=1.000000
I20260812 06:19:56.815907 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: MajorDeltaCompactionOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.164s	user 0.112s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":193,"lbm_read_time_us":11906,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27943,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2500}
I20260812 06:19:56.816630 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=14.095187
I20260812 06:19:56.872193 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.055s	user 0.034s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22417,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:56.872788 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=2.188937
I20260812 06:19:56.885272 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4323,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:56.885959 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling MajorDeltaCompactionOp(aa38b0cef33b4ff29604d801ee712484): perf score=1.000000
I20260812 06:19:57.068477 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: MajorDeltaCompactionOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.182s	user 0.113s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1077,"lbm_read_time_us":12712,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32180,"lbm_writes_lt_1ms":543,"mutex_wait_us":400,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":43008,"update_count":2500}
I20260812 06:19:57.069319 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=14.095187
I20260812 06:19:57.144616 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.075s	user 0.035s	sys 0.030s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":31201,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:57.145078 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=2.188937
I20260812 06:19:57.157085 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4560,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.157559 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling MajorDeltaCompactionOp(aa38b0cef33b4ff29604d801ee712484): perf score=1.000000
I20260812 06:19:57.328332 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: MajorDeltaCompactionOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.171s	user 0.118s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":823,"lbm_read_time_us":12831,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28585,"lbm_writes_lt_1ms":543,"mutex_wait_us":344,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2500}
I20260812 06:19:57.328939 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=14.095187
I20260812 06:19:57.392284 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.063s	user 0.037s	sys 0.023s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":30184,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:57.392843 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=2.188937
I20260812 06:19:57.405161 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4472,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.405719 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling MajorDeltaCompactionOp(aa38b0cef33b4ff29604d801ee712484): perf score=1.000000
I20260812 06:19:57.579798 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: MajorDeltaCompactionOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.174s	user 0.105s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":470,"lbm_read_time_us":12832,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32503,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:57.580416 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=14.095187
I20260812 06:19:57.641938 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.061s	user 0.025s	sys 0.030s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21000,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:19:57.642503 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=2.188937
I20260812 06:19:57.653569 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4257,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.654049 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushMRSOp(aa38b0cef33b4ff29604d801ee712484): perf score=1.000000
I20260812 06:19:57.690026 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushMRSOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.036s	user 0.026s	sys 0.004s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":238,"dirs.run_wall_time_us":1456,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1895,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:57.690912 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling MajorDeltaCompactionOp(aa38b0cef33b4ff29604d801ee712484): perf score=1.000000
I20260812 06:19:57.867025 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: MajorDeltaCompactionOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.176s	user 0.123s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":125,"lbm_read_time_us":13304,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29662,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8192,"update_count":2500}
I20260812 06:19:57.868129 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling LogGCOp(aa38b0cef33b4ff29604d801ee712484): free 124710317 bytes of WAL
I20260812 06:19:57.868575 25292 log_reader.cc:385] T aa38b0cef33b4ff29604d801ee712484: removed 12 log segments from log reader
I20260812 06:19:57.868676 25292 log.cc:1079] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/aa38b0cef33b4ff29604d801ee712484/wal-000000015 (ops 72-76)
I20260812 06:19:57.868757 25292 log.cc:1079] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/aa38b0cef33b4ff29604d801ee712484/wal-000000016 (ops 77-81)
I20260812 06:19:57.868826 25292 log.cc:1079] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/aa38b0cef33b4ff29604d801ee712484/wal-000000017 (ops 82-86)
I20260812 06:19:57.868888 25292 log.cc:1079] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/aa38b0cef33b4ff29604d801ee712484/wal-000000018 (ops 87-91)
I20260812 06:19:57.868955 25292 log.cc:1079] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/aa38b0cef33b4ff29604d801ee712484/wal-000000019 (ops 92-96)
I20260812 06:19:57.869022 25292 log.cc:1079] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/aa38b0cef33b4ff29604d801ee712484/wal-000000020 (ops 97-101)
I20260812 06:19:57.869087 25292 log.cc:1079] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/aa38b0cef33b4ff29604d801ee712484/wal-000000021 (ops 102-106)
I20260812 06:19:57.869158 25292 log.cc:1079] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/aa38b0cef33b4ff29604d801ee712484/wal-000000022 (ops 107-111)
I20260812 06:19:57.869244 25292 log.cc:1079] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/aa38b0cef33b4ff29604d801ee712484/wal-000000023 (ops 112-116)
I20260812 06:19:57.869329 25292 log.cc:1079] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/aa38b0cef33b4ff29604d801ee712484/wal-000000024 (ops 117-121)
I20260812 06:19:57.869415 25292 log.cc:1079] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/aa38b0cef33b4ff29604d801ee712484/wal-000000025 (ops 122-126)
I20260812 06:19:57.869498 25292 log.cc:1079] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/aa38b0cef33b4ff29604d801ee712484/wal-000000026 (ops 127-131)
I20260812 06:19:57.898275 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: LogGCOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.030s	user 0.005s	sys 0.023s Metrics: {}
I20260812 06:19:57.898722 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=18.063937
I20260812 06:19:57.971108 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.072s	user 0.039s	sys 0.030s Metrics: {"bytes_written":20512320,"delete_count":0,"lbm_write_time_us":28933,"lbm_writes_lt_1ms":503,"reinsert_count":0,"spinlock_wait_cycles":4608,"update_count":2500}
I20260812 06:19:57.971639 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling LogGCOp(aa38b0cef33b4ff29604d801ee712484): free 12017954 bytes of WAL
I20260812 06:19:57.971859 25292 log_reader.cc:385] T aa38b0cef33b4ff29604d801ee712484: removed 1 log segments from log reader
I20260812 06:19:57.971902 25292 log.cc:1079] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/aa38b0cef33b4ff29604d801ee712484/wal-000000027 (ops 132-136)
I20260812 06:19:57.974359 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: LogGCOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:57.974684 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=2.188937
I20260812 06:19:57.985078 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.010s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4172,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.985450 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling UndoDeltaBlockGCOp(aa38b0cef33b4ff29604d801ee712484): 493 bytes on disk
I20260812 06:19:57.987399 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: UndoDeltaBlockGCOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4}
I20260812 06:19:57.988030 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling MajorDeltaCompactionOp(aa38b0cef33b4ff29604d801ee712484): perf score=1.000000
I20260812 06:19:58.198196 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: MajorDeltaCompactionOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.210s	user 0.139s	sys 0.068s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877107,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":600,"lbm_read_time_us":14457,"lbm_reads_lt_1ms":672,"lbm_write_time_us":40223,"lbm_writes_lt_1ms":643,"mutex_wait_us":42,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3000}
I20260812 06:19:58.198822 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=14.095187
I20260812 06:19:58.265270 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.066s	user 0.043s	sys 0.012s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":23829,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:58.265878 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=2.188937
I20260812 06:19:58.281384 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.015s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4503,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.281921 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling MajorDeltaCompactionOp(aa38b0cef33b4ff29604d801ee712484): perf score=1.000000
I20260812 06:19:58.466982 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: MajorDeltaCompactionOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.185s	user 0.137s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774692,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1077,"lbm_read_time_us":13422,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31700,"lbm_writes_lt_1ms":543,"mutex_wait_us":258,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":22144,"update_count":2500}
I20260812 06:19:58.467510 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=14.095187
I20260812 06:19:58.529985 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.062s	user 0.033s	sys 0.023s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":25686,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:58.530531 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=2.188937
I20260812 06:19:58.541122 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4265,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.541520 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling MajorDeltaCompactionOp(aa38b0cef33b4ff29604d801ee712484): perf score=1.000000
I20260812 06:19:58.728278 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: MajorDeltaCompactionOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.187s	user 0.119s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":144,"lbm_read_time_us":13343,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29488,"lbm_writes_lt_1ms":543,"mutex_wait_us":30,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19200,"update_count":2500}
I20260812 06:19:58.729066 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=14.095187
I20260812 06:19:58.792912 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.064s	user 0.024s	sys 0.039s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":27583,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:58.793445 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=2.188937
I20260812 06:19:58.803987 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4187,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.804443 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling MajorDeltaCompactionOp(aa38b0cef33b4ff29604d801ee712484): perf score=1.000000
I20260812 06:19:58.996708 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: MajorDeltaCompactionOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.192s	user 0.103s	sys 0.077s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":192,"lbm_read_time_us":13546,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31790,"lbm_writes_lt_1ms":543,"mutex_wait_us":54,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13312,"update_count":2500}
I20260812 06:19:58.997439 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=14.095187
I20260812 06:19:59.049726 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.052s	user 0.034s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24736,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:59.050192 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=2.188937
I20260812 06:19:59.063162 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4778,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:59.063624 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling MajorDeltaCompactionOp(aa38b0cef33b4ff29604d801ee712484): perf score=1.000000
I20260812 06:19:59.244660 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: MajorDeltaCompactionOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.181s	user 0.113s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":215,"lbm_read_time_us":9853,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28272,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:59.245353 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=14.095187
I20260812 06:19:59.301741 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.056s	user 0.038s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25288,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:59.302299 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=2.188937
I20260812 06:19:59.318634 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.016s	user 0.013s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6487,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:59.319170 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushMRSOp(aa38b0cef33b4ff29604d801ee712484): perf score=1.000000
I20260812 06:19:59.346572 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushMRSOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.027s	user 0.023s	sys 0.003s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":53,"dirs.run_cpu_time_us":213,"dirs.run_wall_time_us":1338,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1784,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:59.347213 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling LogGCOp(aa38b0cef33b4ff29604d801ee712484): free 124710562 bytes of WAL
I20260812 06:19:59.347431 25292 log_reader.cc:385] T aa38b0cef33b4ff29604d801ee712484: removed 12 log segments from log reader
I20260812 06:19:59.347491 25292 log.cc:1079] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/aa38b0cef33b4ff29604d801ee712484/wal-000000028 (ops 137-141)
I20260812 06:19:59.347540 25292 log.cc:1079] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/aa38b0cef33b4ff29604d801ee712484/wal-000000029 (ops 142-146)
I20260812 06:19:59.347595 25292 log.cc:1079] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/aa38b0cef33b4ff29604d801ee712484/wal-000000030 (ops 147-151)
I20260812 06:19:59.347640 25292 log.cc:1079] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/aa38b0cef33b4ff29604d801ee712484/wal-000000031 (ops 152-156)
I20260812 06:19:59.347679 25292 log.cc:1079] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/aa38b0cef33b4ff29604d801ee712484/wal-000000032 (ops 157-161)
I20260812 06:19:59.347718 25292 log.cc:1079] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/aa38b0cef33b4ff29604d801ee712484/wal-000000033 (ops 162-166)
I20260812 06:19:59.347759 25292 log.cc:1079] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/aa38b0cef33b4ff29604d801ee712484/wal-000000034 (ops 167-171)
I20260812 06:19:59.347797 25292 log.cc:1079] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/aa38b0cef33b4ff29604d801ee712484/wal-000000035 (ops 172-176)
I20260812 06:19:59.347855 25292 log.cc:1079] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/aa38b0cef33b4ff29604d801ee712484/wal-000000036 (ops 177-181)
I20260812 06:19:59.347896 25292 log.cc:1079] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/aa38b0cef33b4ff29604d801ee712484/wal-000000037 (ops 182-186)
I20260812 06:19:59.347934 25292 log.cc:1079] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/aa38b0cef33b4ff29604d801ee712484/wal-000000038 (ops 187-191)
I20260812 06:19:59.347973 25292 log.cc:1079] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/aa38b0cef33b4ff29604d801ee712484/wal-000000039 (ops 192-196)
I20260812 06:19:59.378818 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: LogGCOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.031s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:19:59.379406 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=3.181125
I20260812 06:19:59.392700 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4430852,"delete_count":0,"lbm_write_time_us":4573,"lbm_writes_lt_1ms":111,"reinsert_count":0,"update_count":540}
I20260812 06:19:59.393126 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484): perf score=2.188937
I20260812 06:19:59.403263 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: FlushDeltaMemStoresOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3774458,"delete_count":0,"lbm_write_time_us":4136,"lbm_writes_lt_1ms":95,"reinsert_count":0,"update_count":460}
I20260812 06:19:59.403659 25387 maintenance_manager.cc:419] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: Scheduling MajorDeltaCompactionOp(aa38b0cef33b4ff29604d801ee712484): perf score=1.000000
I20260812 06:19:59.448442 25119 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.979s	user 1.825s	sys 0.156s
I20260812 06:19:59.549966 25119 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.101s	user 0.000s	sys 0.002s
I20260812 06:19:59.550583 25119 tablet_server.cc:179] TabletServer@127.24.135.193:0 shutting down...
I20260812 06:19:59.600883 25292 maintenance_manager.cc:643] P 8f0a23ceaf1e42d39e09aedea9fcd0ee: MajorDeltaCompactionOp(aa38b0cef33b4ff29604d801ee712484) complete. Timing: real 0.197s	user 0.128s	sys 0.066s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979742,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":492,"lbm_read_time_us":16356,"lbm_reads_lt_1ms":770,"lbm_write_time_us":33281,"lbm_writes_lt_1ms":743,"mutex_wait_us":45,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2560,"thread_start_us":91,"threads_started":1,"update_count":3500}
I20260812 06:19:59.601603 25119 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:59.602037 25119 tablet_replica.cc:333] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee: stopping tablet replica
I20260812 06:19:59.602293 25119 raft_consensus.cc:2243] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:59.602528 25119 raft_consensus.cc:2272] T aa38b0cef33b4ff29604d801ee712484 P 8f0a23ceaf1e42d39e09aedea9fcd0ee [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:59.618232 25119 tablet_server.cc:196] TabletServer@127.24.135.193:0 shutdown complete.
I20260812 06:19:59.655090 25119 master.cc:562] Master@127.24.135.254:44209 shutting down...
I20260812 06:19:59.658967 25119 raft_consensus.cc:2243] T 00000000000000000000000000000000 P f12ffaf6cfcb40c789525f411b296dcb [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:59.659171 25119 raft_consensus.cc:2272] T 00000000000000000000000000000000 P f12ffaf6cfcb40c789525f411b296dcb [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:59.659263 25119 tablet_replica.cc:333] T 00000000000000000000000000000000 P f12ffaf6cfcb40c789525f411b296dcb: stopping tablet replica
I20260812 06:19:59.671674 25119 master.cc:584] Master@127.24.135.254:44209 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5564 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:59.773156 25119 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.24.135.254:41107
I20260812 06:19:59.773586 25119 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:19:59.776119 25119 server_base.cc:1061] running on GCE node
W20260812 06:19:59.776191 25436 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:59.776268 25437 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:59.776407 25439 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:59.776646 25119 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:59.776719 25119 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:59.776763 25119 hybrid_clock.cc:648] HybridClock initialized: now 1786515599776762 us; error 0 us; skew 500 ppm
I20260812 06:19:59.777699 25119 webserver.cc:533] Webserver started at http://127.24.135.254:34203/ using document root <none> and password file <none>
I20260812 06:19:59.777886 25119 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:59.777962 25119 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:59.778050 25119 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:59.778438 25119 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/master-0-root/instance:
uuid: "055b95f8364a4b25a3457a3003725869"
format_stamp: "Formatted at 2026-08-12 06:19:59 on dist-test-slave-04bb"
I20260812 06:19:59.779960 25119 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:59.781009 25447 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:59.781320 25119 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:59.781392 25119 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/master-0-root
uuid: "055b95f8364a4b25a3457a3003725869"
format_stamp: "Formatted at 2026-08-12 06:19:59 on dist-test-slave-04bb"
I20260812 06:19:59.781486 25119 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-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:59.786067 25119 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:59.786397 25119 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:59.790598 25119 rpc_server.cc:307] RPC server started. Bound to: 127.24.135.254:41107
I20260812 06:19:59.797693 25536 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.135.254:41107 every 8 connection(s)
I20260812 06:19:59.797693 25537 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:59.799556 25537 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 055b95f8364a4b25a3457a3003725869: Bootstrap starting.
I20260812 06:19:59.800374 25537 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 055b95f8364a4b25a3457a3003725869: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:59.801452 25537 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 055b95f8364a4b25a3457a3003725869: No bootstrap required, opened a new log
I20260812 06:19:59.801859 25537 raft_consensus.cc:359] T 00000000000000000000000000000000 P 055b95f8364a4b25a3457a3003725869 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "055b95f8364a4b25a3457a3003725869" member_type: VOTER }
I20260812 06:19:59.801944 25537 raft_consensus.cc:385] T 00000000000000000000000000000000 P 055b95f8364a4b25a3457a3003725869 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:59.802000 25537 raft_consensus.cc:740] T 00000000000000000000000000000000 P 055b95f8364a4b25a3457a3003725869 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 055b95f8364a4b25a3457a3003725869, State: Initialized, Role: FOLLOWER
I20260812 06:19:59.802182 25537 consensus_queue.cc:260] T 00000000000000000000000000000000 P 055b95f8364a4b25a3457a3003725869 [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: "055b95f8364a4b25a3457a3003725869" member_type: VOTER }
I20260812 06:19:59.802270 25537 raft_consensus.cc:399] T 00000000000000000000000000000000 P 055b95f8364a4b25a3457a3003725869 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:59.802335 25537 raft_consensus.cc:493] T 00000000000000000000000000000000 P 055b95f8364a4b25a3457a3003725869 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:59.802394 25537 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 055b95f8364a4b25a3457a3003725869 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:59.803047 25537 raft_consensus.cc:515] T 00000000000000000000000000000000 P 055b95f8364a4b25a3457a3003725869 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "055b95f8364a4b25a3457a3003725869" member_type: VOTER }
I20260812 06:19:59.803194 25537 leader_election.cc:304] T 00000000000000000000000000000000 P 055b95f8364a4b25a3457a3003725869 [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: 055b95f8364a4b25a3457a3003725869; no voters: 
I20260812 06:19:59.803401 25537 leader_election.cc:290] T 00000000000000000000000000000000 P 055b95f8364a4b25a3457a3003725869 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:59.803534 25543 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 055b95f8364a4b25a3457a3003725869 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:59.803758 25543 raft_consensus.cc:697] T 00000000000000000000000000000000 P 055b95f8364a4b25a3457a3003725869 [term 1 LEADER]: Becoming Leader. State: Replica: 055b95f8364a4b25a3457a3003725869, State: Running, Role: LEADER
I20260812 06:19:59.803947 25543 consensus_queue.cc:237] T 00000000000000000000000000000000 P 055b95f8364a4b25a3457a3003725869 [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: "055b95f8364a4b25a3457a3003725869" member_type: VOTER }
I20260812 06:19:59.803982 25537 sys_catalog.cc:565] T 00000000000000000000000000000000 P 055b95f8364a4b25a3457a3003725869 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:59.804385 25549 sys_catalog.cc:455] T 00000000000000000000000000000000 P 055b95f8364a4b25a3457a3003725869 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 055b95f8364a4b25a3457a3003725869. Latest consensus state: current_term: 1 leader_uuid: "055b95f8364a4b25a3457a3003725869" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "055b95f8364a4b25a3457a3003725869" member_type: VOTER } }
I20260812 06:19:59.804371 25547 sys_catalog.cc:455] T 00000000000000000000000000000000 P 055b95f8364a4b25a3457a3003725869 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "055b95f8364a4b25a3457a3003725869" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "055b95f8364a4b25a3457a3003725869" member_type: VOTER } }
I20260812 06:19:59.804481 25549 sys_catalog.cc:458] T 00000000000000000000000000000000 P 055b95f8364a4b25a3457a3003725869 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:59.804493 25547 sys_catalog.cc:458] T 00000000000000000000000000000000 P 055b95f8364a4b25a3457a3003725869 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:59.804777 25552 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:59.805612 25552 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:59.806022 25119 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:59.807549 25552 catalog_manager.cc:1383] Generated new cluster ID: 6a4e1eefd81847d9a28bce3c3318613c
I20260812 06:19:59.807654 25552 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:59.837637 25552 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:59.838310 25552 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:59.848755 25552 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 055b95f8364a4b25a3457a3003725869: Generated new TSK 0
I20260812 06:19:59.848956 25552 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:59.870652 25119 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:19:59.872983 25119 server_base.cc:1061] running on GCE node
W20260812 06:19:59.872961 25576 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:59.872959 25577 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:59.872951 25579 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:59.873497 25119 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:59.873570 25119 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:59.873600 25119 hybrid_clock.cc:648] HybridClock initialized: now 1786515599873599 us; error 0 us; skew 500 ppm
I20260812 06:19:59.874485 25119 webserver.cc:533] Webserver started at http://127.24.135.193:39347/ using document root <none> and password file <none>
I20260812 06:19:59.874697 25119 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:59.874779 25119 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:59.874866 25119 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:59.875334 25119 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/instance:
uuid: "c16dda5fea1b45189f4f389abadf4de5"
format_stamp: "Formatted at 2026-08-12 06:19:59 on dist-test-slave-04bb"
I20260812 06:19:59.877070 25119 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:59.878159 25588 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:59.878436 25119 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:59.878527 25119 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root
uuid: "c16dda5fea1b45189f4f389abadf4de5"
format_stamp: "Formatted at 2026-08-12 06:19:59 on dist-test-slave-04bb"
I20260812 06:19:59.878616 25119 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-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:59.887023 25119 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:59.887387 25119 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:59.887686 25119 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:59.888144 25119 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:59.888206 25119 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:59.888266 25119 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:59.888299 25119 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:59.892781 25119 rpc_server.cc:307] RPC server started. Bound to: 127.24.135.193:44727
I20260812 06:19:59.893348 25704 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.135.193:44727 every 8 connection(s)
I20260812 06:19:59.902447 25705 heartbeater.cc:344] Connected to a master server at 127.24.135.254:41107
I20260812 06:19:59.902590 25705 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:59.902854 25705 heartbeater.cc:507] Master 127.24.135.254:41107 requested a full tablet report, sending...
I20260812 06:19:59.903614 25477 ts_manager.cc:194] Registered new tserver with Master: c16dda5fea1b45189f4f389abadf4de5 (127.24.135.193:44727)
I20260812 06:19:59.903663 25119 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01021489s
I20260812 06:19:59.904692 25477 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:42186
I20260812 06:19:59.911062 25477 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:42194:
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:59.919728 25636 tablet_service.cc:1511] Processing CreateTablet for tablet 21a15294f4b94130915f88c2b81248b6 (DEFAULT_TABLE table=heavy-update-compaction-test [id=60ae018f960b454985bf913e6cfe9bdd]), partition=
I20260812 06:19:59.920027 25636 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 21a15294f4b94130915f88c2b81248b6. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:59.922214 25725 tablet_bootstrap.cc:492] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Bootstrap starting.
I20260812 06:19:59.923046 25725 tablet_bootstrap.cc:654] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:59.923985 25725 tablet_bootstrap.cc:492] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: No bootstrap required, opened a new log
I20260812 06:19:59.924058 25725 ts_tablet_manager.cc:1403] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:59.924376 25725 raft_consensus.cc:359] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c16dda5fea1b45189f4f389abadf4de5" member_type: VOTER last_known_addr { host: "127.24.135.193" port: 44727 } }
I20260812 06:19:59.924458 25725 raft_consensus.cc:385] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:59.924479 25725 raft_consensus.cc:740] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c16dda5fea1b45189f4f389abadf4de5, State: Initialized, Role: FOLLOWER
I20260812 06:19:59.924634 25725 consensus_queue.cc:260] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5 [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: "c16dda5fea1b45189f4f389abadf4de5" member_type: VOTER last_known_addr { host: "127.24.135.193" port: 44727 } }
I20260812 06:19:59.924710 25725 raft_consensus.cc:399] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:59.924767 25725 raft_consensus.cc:493] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:59.924810 25725 raft_consensus.cc:3060] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:59.925793 25725 raft_consensus.cc:515] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c16dda5fea1b45189f4f389abadf4de5" member_type: VOTER last_known_addr { host: "127.24.135.193" port: 44727 } }
I20260812 06:19:59.925910 25725 leader_election.cc:304] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5 [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: c16dda5fea1b45189f4f389abadf4de5; no voters: 
I20260812 06:19:59.926059 25725 leader_election.cc:290] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:59.926241 25731 raft_consensus.cc:2804] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:59.926478 25731 raft_consensus.cc:697] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5 [term 1 LEADER]: Becoming Leader. State: Replica: c16dda5fea1b45189f4f389abadf4de5, State: Running, Role: LEADER
I20260812 06:19:59.926491 25725 ts_tablet_manager.cc:1434] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:59.926517 25705 heartbeater.cc:499] Master 127.24.135.254:41107 was elected leader, sending a full tablet report...
I20260812 06:19:59.926715 25731 consensus_queue.cc:237] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5 [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: "c16dda5fea1b45189f4f389abadf4de5" member_type: VOTER last_known_addr { host: "127.24.135.193" port: 44727 } }
I20260812 06:19:59.928046 25477 catalog_manager.cc:5719] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5 reported cstate change: term changed from 0 to 1, leader changed from <none> to c16dda5fea1b45189f4f389abadf4de5 (127.24.135.193). New cstate: current_term: 1 leader_uuid: "c16dda5fea1b45189f4f389abadf4de5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c16dda5fea1b45189f4f389abadf4de5" member_type: VOTER last_known_addr { host: "127.24.135.193" port: 44727 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:59.989878 25119 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.016s	sys 0.006s
I20260812 06:20:00.143836 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushMRSOp(21a15294f4b94130915f88c2b81248b6): perf score=19.054940
I20260812 06:20:00.311328 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushMRSOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.167s	user 0.102s	sys 0.063s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":180,"dirs.run_wall_time_us":841,"drs_written":1,"lbm_read_time_us":109,"lbm_reads_lt_1ms":4,"lbm_write_time_us":45514,"lbm_writes_lt_1ms":767,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":1792,"update_count":1500}
I20260812 06:20:00.312163 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling LogGCOp(21a15294f4b94130915f88c2b81248b6): free 20743880 bytes of WAL
I20260812 06:20:00.312456 25596 log_reader.cc:385] T 21a15294f4b94130915f88c2b81248b6: removed 2 log segments from log reader
I20260812 06:20:00.312558 25596 log.cc:1079] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/21a15294f4b94130915f88c2b81248b6/wal-000000001 (ops 1-6)
I20260812 06:20:00.312630 25596 log.cc:1079] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/21a15294f4b94130915f88c2b81248b6/wal-000000002 (ops 7-11)
I20260812 06:20:00.319301 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: LogGCOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.007s	user 0.002s	sys 0.003s Metrics: {}
I20260812 06:20:00.319682 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling UndoDeltaBlockGCOp(21a15294f4b94130915f88c2b81248b6): 16821647 bytes on disk
I20260812 06:20:00.320052 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: UndoDeltaBlockGCOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4}
I20260812 06:20:00.320453 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=2.188937
I20260812 06:20:00.345939 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.025s	user 0.007s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5327,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:00.346446 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=2.188937
I20260812 06:20:00.355926 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3623,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:00.356413 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling MajorDeltaCompactionOp(21a15294f4b94130915f88c2b81248b6): perf score=1.000000
I20260812 06:20:00.546895 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: MajorDeltaCompactionOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.190s	user 0.113s	sys 0.076s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24405549,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":545,"lbm_read_time_us":15438,"lbm_reads_lt_1ms":559,"lbm_write_time_us":30737,"lbm_writes_lt_1ms":533,"mutex_wait_us":61,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":21120,"thread_start_us":345,"threads_started":5,"update_count":2450}
I20260812 06:20:00.547487 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=14.095187
I20260812 06:20:00.594496 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.047s	user 0.026s	sys 0.019s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21066,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:00.595021 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling MajorDeltaCompactionOp(21a15294f4b94130915f88c2b81248b6): perf score=1.000000
I20260812 06:20:00.768884 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: MajorDeltaCompactionOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.174s	user 0.125s	sys 0.039s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713154,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":145,"lbm_read_time_us":12061,"lbm_reads_lt_1ms":467,"lbm_write_time_us":30047,"lbm_writes_lt_1ms":443,"mutex_wait_us":66,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":2000}
I20260812 06:20:00.769590 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=14.095187
I20260812 06:20:00.815584 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.046s	user 0.022s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20954,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:00.816045 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=2.188937
I20260812 06:20:00.828029 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4272,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:00.828656 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling MajorDeltaCompactionOp(21a15294f4b94130915f88c2b81248b6): perf score=1.000000
I20260812 06:20:01.018473 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: MajorDeltaCompactionOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.190s	user 0.114s	sys 0.072s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":228,"lbm_read_time_us":12992,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32050,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2500}
I20260812 06:20:01.019160 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=14.095187
I20260812 06:20:01.073084 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.054s	user 0.033s	sys 0.012s Metrics: {"bytes_written":16409882,"delete_count":0,"lbm_write_time_us":19871,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:01.073566 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=2.188937
I20260812 06:20:01.090129 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.016s	user 0.013s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6507,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:01.090654 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling MajorDeltaCompactionOp(21a15294f4b94130915f88c2b81248b6): perf score=1.000000
I20260812 06:20:01.254395 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: MajorDeltaCompactionOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.164s	user 0.122s	sys 0.037s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815664,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":569,"lbm_read_time_us":12416,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29579,"lbm_writes_lt_1ms":543,"mutex_wait_us":129,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":2500}
I20260812 06:20:01.254855 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=11.118625
I20260812 06:20:01.291539 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.037s	user 0.026s	sys 0.008s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15727,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:01.292243 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=2.188937
I20260812 06:20:01.307240 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.015s	user 0.011s	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:20:01.307686 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling MajorDeltaCompactionOp(21a15294f4b94130915f88c2b81248b6): perf score=1.000000
I20260812 06:20:01.439589 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: MajorDeltaCompactionOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.132s	user 0.107s	sys 0.024s 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":311,"lbm_read_time_us":7669,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26736,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1152,"update_count":2000}
I20260812 06:20:01.440240 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=10.126437
I20260812 06:20:01.484302 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.044s	user 0.019s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14816,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:01.484779 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=2.188937
I20260812 06:20:01.494946 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3922,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:01.495378 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling MajorDeltaCompactionOp(21a15294f4b94130915f88c2b81248b6): perf score=1.000000
I20260812 06:20:01.623193 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: MajorDeltaCompactionOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.128s	user 0.097s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":200,"lbm_read_time_us":10046,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24346,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":22272,"update_count":2000}
I20260812 06:20:01.623847 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=10.126437
I20260812 06:20:01.689922 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.066s	user 0.018s	sys 0.046s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":23300,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:01.690603 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=2.188937
I20260812 06:20:01.709226 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.018s	user 0.004s	sys 0.014s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7081,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:01.709811 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushMRSOp(21a15294f4b94130915f88c2b81248b6): perf score=1.000000
I20260812 06:20:01.751338 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushMRSOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.041s	user 0.036s	sys 0.001s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":101,"dirs.run_cpu_time_us":273,"dirs.run_wall_time_us":1446,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1709,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:20:01.752002 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling LogGCOp(21a15294f4b94130915f88c2b81248b6): free 124710243 bytes of WAL
I20260812 06:20:01.752254 25596 log_reader.cc:385] T 21a15294f4b94130915f88c2b81248b6: removed 12 log segments from log reader
I20260812 06:20:01.752300 25596 log.cc:1079] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/21a15294f4b94130915f88c2b81248b6/wal-000000003 (ops 12-16)
I20260812 06:20:01.752329 25596 log.cc:1079] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/21a15294f4b94130915f88c2b81248b6/wal-000000004 (ops 17-21)
I20260812 06:20:01.752384 25596 log.cc:1079] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/21a15294f4b94130915f88c2b81248b6/wal-000000005 (ops 22-26)
I20260812 06:20:01.752430 25596 log.cc:1079] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/21a15294f4b94130915f88c2b81248b6/wal-000000006 (ops 27-31)
I20260812 06:20:01.752449 25596 log.cc:1079] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/21a15294f4b94130915f88c2b81248b6/wal-000000007 (ops 32-36)
I20260812 06:20:01.752507 25596 log.cc:1079] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/21a15294f4b94130915f88c2b81248b6/wal-000000008 (ops 37-41)
I20260812 06:20:01.752599 25596 log.cc:1079] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/21a15294f4b94130915f88c2b81248b6/wal-000000009 (ops 42-46)
I20260812 06:20:01.752641 25596 log.cc:1079] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/21a15294f4b94130915f88c2b81248b6/wal-000000010 (ops 47-51)
I20260812 06:20:01.752686 25596 log.cc:1079] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/21a15294f4b94130915f88c2b81248b6/wal-000000011 (ops 52-56)
I20260812 06:20:01.752723 25596 log.cc:1079] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/21a15294f4b94130915f88c2b81248b6/wal-000000012 (ops 57-61)
I20260812 06:20:01.752761 25596 log.cc:1079] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/21a15294f4b94130915f88c2b81248b6/wal-000000013 (ops 62-66)
I20260812 06:20:01.752799 25596 log.cc:1079] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/21a15294f4b94130915f88c2b81248b6/wal-000000014 (ops 67-71)
I20260812 06:20:01.779400 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: LogGCOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.027s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:20:01.779958 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling UndoDeltaBlockGCOp(21a15294f4b94130915f88c2b81248b6): 473 bytes on disk
I20260812 06:20:01.780441 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: UndoDeltaBlockGCOp(21a15294f4b94130915f88c2b81248b6) 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:20:01.781194 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=2.188937
I20260812 06:20:01.804514 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.023s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6073,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:01.805236 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=2.188937
I20260812 06:20:01.816138 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4438,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:01.816606 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling MajorDeltaCompactionOp(21a15294f4b94130915f88c2b81248b6): perf score=1.000000
I20260812 06:20:02.025701 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: MajorDeltaCompactionOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.209s	user 0.124s	sys 0.084s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918333,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":150,"lbm_read_time_us":15657,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31964,"lbm_writes_lt_1ms":643,"mutex_wait_us":53,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":17536,"thread_start_us":101,"threads_started":1,"update_count":3000}
I20260812 06:20:02.026502 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=14.095187
I20260812 06:20:02.069044 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.042s	user 0.034s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18890,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:02.069473 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=2.188937
I20260812 06:20:02.079623 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.010s	user 0.004s	sys 0.004s 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:20:02.080067 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling MajorDeltaCompactionOp(21a15294f4b94130915f88c2b81248b6): perf score=1.000000
I20260812 06:20:02.274893 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: MajorDeltaCompactionOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.195s	user 0.125s	sys 0.069s 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":263,"lbm_read_time_us":14367,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32876,"lbm_writes_lt_1ms":543,"mutex_wait_us":42,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2500}
I20260812 06:20:02.275483 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=14.095187
I20260812 06:20:02.337639 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.062s	user 0.036s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19311,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:02.338192 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=2.188937
I20260812 06:20:02.349776 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4328,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:02.351701 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling MajorDeltaCompactionOp(21a15294f4b94130915f88c2b81248b6): perf score=1.000000
I20260812 06:20:02.528796 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: MajorDeltaCompactionOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.177s	user 0.121s	sys 0.056s 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":983,"lbm_read_time_us":12826,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30047,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2500}
I20260812 06:20:02.529445 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=14.095187
I20260812 06:20:02.595104 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.065s	user 0.043s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24717,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:02.595626 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=2.188937
I20260812 06:20:02.606856 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4320,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:02.607280 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling MajorDeltaCompactionOp(21a15294f4b94130915f88c2b81248b6): perf score=1.000000
I20260812 06:20:02.793529 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: MajorDeltaCompactionOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.186s	user 0.114s	sys 0.064s 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":132,"lbm_read_time_us":13005,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30024,"lbm_writes_lt_1ms":543,"mutex_wait_us":18,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":2500}
I20260812 06:20:02.794140 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=14.095187
I20260812 06:20:02.847162 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.053s	user 0.018s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20198,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:02.847652 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=2.188937
I20260812 06:20:02.868793 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.021s	user 0.010s	sys 0.011s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4304,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:02.869267 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling MajorDeltaCompactionOp(21a15294f4b94130915f88c2b81248b6): perf score=1.000000
I20260812 06:20:03.047456 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: MajorDeltaCompactionOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.178s	user 0.113s	sys 0.065s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":226,"lbm_read_time_us":12454,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28903,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16128,"update_count":2500}
I20260812 06:20:03.048178 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=14.095187
I20260812 06:20:03.101956 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.054s	user 0.025s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24162,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:03.102475 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=2.188937
I20260812 06:20:03.113974 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4252,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.114547 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling MajorDeltaCompactionOp(21a15294f4b94130915f88c2b81248b6): perf score=1.000000
I20260812 06:20:03.298758 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: MajorDeltaCompactionOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.184s	user 0.112s	sys 0.060s 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":893,"lbm_read_time_us":9368,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29597,"lbm_writes_lt_1ms":543,"mutex_wait_us":276,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":2500}
I20260812 06:20:03.299365 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=14.095187
I20260812 06:20:03.347941 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.048s	user 0.017s	sys 0.028s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21309,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:03.348610 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=2.188937
I20260812 06:20:03.359889 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4075,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.360368 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushMRSOp(21a15294f4b94130915f88c2b81248b6): perf score=1.000000
I20260812 06:20:03.391793 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushMRSOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.031s	user 0.026s	sys 0.003s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":206,"dirs.run_wall_time_us":1376,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1512,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:20:03.392416 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling LogGCOp(21a15294f4b94130915f88c2b81248b6): free 132571389 bytes of WAL
I20260812 06:20:03.392660 25596 log_reader.cc:385] T 21a15294f4b94130915f88c2b81248b6: removed 13 log segments from log reader
I20260812 06:20:03.392722 25596 log.cc:1079] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/21a15294f4b94130915f88c2b81248b6/wal-000000015 (ops 72-76)
I20260812 06:20:03.392771 25596 log.cc:1079] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/21a15294f4b94130915f88c2b81248b6/wal-000000016 (ops 77-81)
I20260812 06:20:03.392829 25596 log.cc:1079] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/21a15294f4b94130915f88c2b81248b6/wal-000000017 (ops 82-86)
I20260812 06:20:03.392874 25596 log.cc:1079] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/21a15294f4b94130915f88c2b81248b6/wal-000000018 (ops 87-90)
I20260812 06:20:03.392911 25596 log.cc:1079] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/21a15294f4b94130915f88c2b81248b6/wal-000000019 (ops 91-95)
I20260812 06:20:03.392951 25596 log.cc:1079] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/21a15294f4b94130915f88c2b81248b6/wal-000000020 (ops 96-100)
I20260812 06:20:03.392988 25596 log.cc:1079] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/21a15294f4b94130915f88c2b81248b6/wal-000000021 (ops 101-105)
I20260812 06:20:03.393028 25596 log.cc:1079] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/21a15294f4b94130915f88c2b81248b6/wal-000000022 (ops 106-110)
I20260812 06:20:03.393065 25596 log.cc:1079] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/21a15294f4b94130915f88c2b81248b6/wal-000000023 (ops 111-115)
I20260812 06:20:03.393105 25596 log.cc:1079] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/21a15294f4b94130915f88c2b81248b6/wal-000000024 (ops 116-120)
I20260812 06:20:03.393142 25596 log.cc:1079] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/21a15294f4b94130915f88c2b81248b6/wal-000000025 (ops 121-125)
I20260812 06:20:03.393180 25596 log.cc:1079] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/21a15294f4b94130915f88c2b81248b6/wal-000000026 (ops 126-130)
I20260812 06:20:03.393219 25596 log.cc:1079] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/21a15294f4b94130915f88c2b81248b6/wal-000000027 (ops 131-134)
I20260812 06:20:03.426874 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: LogGCOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.034s	user 0.001s	sys 0.031s Metrics: {}
I20260812 06:20:03.427369 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling UndoDeltaBlockGCOp(21a15294f4b94130915f88c2b81248b6): 491 bytes on disk
I20260812 06:20:03.427853 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: UndoDeltaBlockGCOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:20:03.428413 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=3.181125
I20260812 06:20:03.451545 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.023s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":7380,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:03.452044 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=2.188937
I20260812 06:20:03.461992 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3776,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:03.462437 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling MajorDeltaCompactionOp(21a15294f4b94130915f88c2b81248b6): perf score=1.000000
I20260812 06:20:03.697949 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: MajorDeltaCompactionOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.235s	user 0.151s	sys 0.082s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020732,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":236,"lbm_read_time_us":15672,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39305,"lbm_writes_lt_1ms":743,"mutex_wait_us":50,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":15232,"thread_start_us":124,"threads_started":1,"update_count":3500}
I20260812 06:20:03.699971 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=18.063937
I20260812 06:20:03.768301 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.068s	user 0.037s	sys 0.016s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":25978,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:03.768798 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=2.188937
I20260812 06:20:03.784564 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6173,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.785045 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling MajorDeltaCompactionOp(21a15294f4b94130915f88c2b81248b6): perf score=1.000000
I20260812 06:20:03.998492 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: MajorDeltaCompactionOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.213s	user 0.128s	sys 0.085s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918099,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":232,"lbm_read_time_us":14733,"lbm_reads_lt_1ms":672,"lbm_write_time_us":36964,"lbm_writes_lt_1ms":643,"mutex_wait_us":58,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":19712,"update_count":3000}
I20260812 06:20:03.999168 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=14.095187
I20260812 06:20:04.059975 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.061s	user 0.036s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26492,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:04.060700 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling MajorDeltaCompactionOp(21a15294f4b94130915f88c2b81248b6): perf score=1.000000
I20260812 06:20:04.234800 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: MajorDeltaCompactionOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.174s	user 0.111s	sys 0.056s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713153,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":287,"lbm_read_time_us":13834,"lbm_reads_lt_1ms":463,"lbm_write_time_us":25410,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:04.235540 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=14.095187
I20260812 06:20:04.288089 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.052s	user 0.044s	sys 0.003s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":23019,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:04.288681 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=2.188937
I20260812 06:20:04.300153 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4213,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:04.300697 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling MajorDeltaCompactionOp(21a15294f4b94130915f88c2b81248b6): perf score=1.000000
I20260812 06:20:04.505067 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: MajorDeltaCompactionOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.204s	user 0.131s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815680,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":761,"lbm_read_time_us":12311,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30992,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12800,"update_count":2500}
I20260812 06:20:04.505722 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=14.095187
I20260812 06:20:04.551715 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.046s	user 0.034s	sys 0.009s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20582,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:04.552150 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=2.188937
I20260812 06:20:04.564918 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.013s	user 0.005s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4751,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:04.565357 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling MajorDeltaCompactionOp(21a15294f4b94130915f88c2b81248b6): perf score=1.000000
I20260812 06:20:04.724009 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: MajorDeltaCompactionOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.158s	user 0.115s	sys 0.037s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815681,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":578,"lbm_read_time_us":10609,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31558,"lbm_writes_lt_1ms":543,"mutex_wait_us":280,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2500}
I20260812 06:20:04.724778 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=14.095187
I20260812 06:20:04.769399 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.044s	user 0.031s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20366,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:04.769905 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=2.188937
I20260812 06:20:04.781908 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.012s	user 0.009s	sys 0.002s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4337,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:04.782493 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling MajorDeltaCompactionOp(21a15294f4b94130915f88c2b81248b6): perf score=1.000000
I20260812 06:20:04.949239 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: MajorDeltaCompactionOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.166s	user 0.111s	sys 0.045s 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":161,"lbm_read_time_us":10568,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33898,"lbm_writes_lt_1ms":543,"mutex_wait_us":37,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2500}
I20260812 06:20:04.949816 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=14.095187
I20260812 06:20:04.998037 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.048s	user 0.028s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20758,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:04.998637 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=2.188937
I20260812 06:20:05.014086 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6106,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:05.014593 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushMRSOp(21a15294f4b94130915f88c2b81248b6): perf score=1.000000
I20260812 06:20:05.053366 25119 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.063s	user 1.867s	sys 0.201s
I20260812 06:20:05.055096 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushMRSOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.040s	user 0.036s	sys 0.000s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":233,"dirs.run_wall_time_us":1418,"drs_written":1,"lbm_read_time_us":100,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2309,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:20:05.055763 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling LogGCOp(21a15294f4b94130915f88c2b81248b6): free 133024646 bytes of WAL
I20260812 06:20:05.055979 25596 log_reader.cc:385] T 21a15294f4b94130915f88c2b81248b6: removed 13 log segments from log reader
I20260812 06:20:05.056047 25596 log.cc:1079] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/21a15294f4b94130915f88c2b81248b6/wal-000000028 (ops 135-139)
I20260812 06:20:05.056098 25596 log.cc:1079] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/21a15294f4b94130915f88c2b81248b6/wal-000000029 (ops 140-144)
I20260812 06:20:05.056166 25596 log.cc:1079] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/21a15294f4b94130915f88c2b81248b6/wal-000000030 (ops 145-149)
I20260812 06:20:05.056207 25596 log.cc:1079] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/21a15294f4b94130915f88c2b81248b6/wal-000000031 (ops 150-154)
I20260812 06:20:05.056244 25596 log.cc:1079] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/21a15294f4b94130915f88c2b81248b6/wal-000000032 (ops 155-159)
I20260812 06:20:05.056282 25596 log.cc:1079] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/21a15294f4b94130915f88c2b81248b6/wal-000000033 (ops 160-164)
I20260812 06:20:05.056319 25596 log.cc:1079] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/21a15294f4b94130915f88c2b81248b6/wal-000000034 (ops 165-169)
I20260812 06:20:05.056357 25596 log.cc:1079] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/21a15294f4b94130915f88c2b81248b6/wal-000000035 (ops 170-174)
I20260812 06:20:05.056393 25596 log.cc:1079] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/21a15294f4b94130915f88c2b81248b6/wal-000000036 (ops 175-179)
I20260812 06:20:05.056430 25596 log.cc:1079] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/21a15294f4b94130915f88c2b81248b6/wal-000000037 (ops 180-184)
I20260812 06:20:05.056468 25596 log.cc:1079] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/21a15294f4b94130915f88c2b81248b6/wal-000000038 (ops 185-188)
I20260812 06:20:05.056504 25596 log.cc:1079] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/21a15294f4b94130915f88c2b81248b6/wal-000000039 (ops 189-193)
I20260812 06:20:05.056565 25596 log.cc:1079] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: Deleting log segment in path: /tmp/dist-test-taskv4KvOV/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515594184931-25119-0/minicluster-data/ts-0-root/wals/21a15294f4b94130915f88c2b81248b6/wal-000000040 (ops 194-198)
I20260812 06:20:05.082229 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: LogGCOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:20:05.082832 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6): perf score=2.188937
I20260812 06:20:05.093451 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: FlushDeltaMemStoresOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4232,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:05.093986 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling UndoDeltaBlockGCOp(21a15294f4b94130915f88c2b81248b6): 493 bytes on disk
I20260812 06:20:05.094568 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: UndoDeltaBlockGCOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:20:05.095202 25706 maintenance_manager.cc:419] P c16dda5fea1b45189f4f389abadf4de5: Scheduling MajorDeltaCompactionOp(21a15294f4b94130915f88c2b81248b6): perf score=1.000000
I20260812 06:20:05.103200 25119 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.049s	user 0.001s	sys 0.000s
I20260812 06:20:05.103718 25119 tablet_server.cc:179] TabletServer@127.24.135.193:0 shutting down...
I20260812 06:20:05.228258 25596 maintenance_manager.cc:643] P c16dda5fea1b45189f4f389abadf4de5: MajorDeltaCompactionOp(21a15294f4b94130915f88c2b81248b6) complete. Timing: real 0.133s	user 0.105s	sys 0.027s Metrics: {"cfile_cache_hit":532,"cfile_cache_hit_bytes":24815684,"cfile_cache_miss":101,"cfile_cache_miss_bytes":4102531,"cfile_init":3,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":974,"lbm_read_time_us":3032,"lbm_reads_lt_1ms":113,"lbm_write_time_us":30608,"lbm_writes_lt_1ms":643,"mutex_wait_us":30,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":32896,"thread_start_us":91,"threads_started":1,"update_count":3000}
I20260812 06:20:05.228809 25119 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:05.229072 25119 tablet_replica.cc:333] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5: stopping tablet replica
I20260812 06:20:05.229277 25119 raft_consensus.cc:2243] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:05.229460 25119 raft_consensus.cc:2272] T 21a15294f4b94130915f88c2b81248b6 P c16dda5fea1b45189f4f389abadf4de5 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:05.244005 25119 tablet_server.cc:196] TabletServer@127.24.135.193:0 shutdown complete.
I20260812 06:20:05.278221 25119 master.cc:562] Master@127.24.135.254:41107 shutting down...
I20260812 06:20:05.281551 25119 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 055b95f8364a4b25a3457a3003725869 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:05.281775 25119 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 055b95f8364a4b25a3457a3003725869 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:05.281862 25119 tablet_replica.cc:333] T 00000000000000000000000000000000 P 055b95f8364a4b25a3457a3003725869: stopping tablet replica
I20260812 06:20:05.294363 25119 master.cc:584] Master@127.24.135.254:41107 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5621 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11186 ms total)

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