[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:17:11.718971 25840 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.25.60.62:33853
I20260812 06:17:11.720016 25840 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:17:11.720670 25840 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:11.726992 25846 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:11.727046 25840 server_base.cc:1061] running on GCE node
W20260812 06:17:11.727234 25847 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:11.726955 25851 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:11.727715 25840 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:11.727854 25840 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:11.727923 25840 hybrid_clock.cc:648] HybridClock initialized: now 1786515431727920 us; error 0 us; skew 500 ppm
I20260812 06:17:11.729730 25840 webserver.cc:533] Webserver started at http://127.25.60.62:43737/ using document root <none> and password file <none>
I20260812 06:17:11.730290 25840 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:11.730382 25840 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:11.730640 25840 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:11.732277 25840 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/master-0-root/instance:
uuid: "7bbbed38999e465db5bb4764b6a303d0"
format_stamp: "Formatted at 2026-08-12 06:17:11 on dist-test-slave-44d2"
I20260812 06:17:11.735793 25840 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:11.737879 25862 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:11.738816 25840 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:17:11.738952 25840 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/master-0-root
uuid: "7bbbed38999e465db5bb4764b6a303d0"
format_stamp: "Formatted at 2026-08-12 06:17:11 on dist-test-slave-44d2"
I20260812 06:17:11.739058 25840 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:11.762632 25840 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:11.763338 25840 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:17:11.763537 25840 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:11.771521 25840 rpc_server.cc:307] RPC server started. Bound to: 127.25.60.62:33853
I20260812 06:17:11.771531 25945 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.60.62:33853 every 8 connection(s)
I20260812 06:17:11.773928 25946 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:11.779327 25946 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 7bbbed38999e465db5bb4764b6a303d0: Bootstrap starting.
I20260812 06:17:11.781824 25946 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 7bbbed38999e465db5bb4764b6a303d0: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:11.782703 25946 log.cc:826] T 00000000000000000000000000000000 P 7bbbed38999e465db5bb4764b6a303d0: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:11.784400 25946 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 7bbbed38999e465db5bb4764b6a303d0: No bootstrap required, opened a new log
I20260812 06:17:11.787191 25946 raft_consensus.cc:359] T 00000000000000000000000000000000 P 7bbbed38999e465db5bb4764b6a303d0 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7bbbed38999e465db5bb4764b6a303d0" member_type: VOTER }
I20260812 06:17:11.787354 25946 raft_consensus.cc:385] T 00000000000000000000000000000000 P 7bbbed38999e465db5bb4764b6a303d0 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:11.787396 25946 raft_consensus.cc:740] T 00000000000000000000000000000000 P 7bbbed38999e465db5bb4764b6a303d0 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 7bbbed38999e465db5bb4764b6a303d0, State: Initialized, Role: FOLLOWER
I20260812 06:17:11.787971 25946 consensus_queue.cc:260] T 00000000000000000000000000000000 P 7bbbed38999e465db5bb4764b6a303d0 [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: "7bbbed38999e465db5bb4764b6a303d0" member_type: VOTER }
I20260812 06:17:11.788105 25946 raft_consensus.cc:399] T 00000000000000000000000000000000 P 7bbbed38999e465db5bb4764b6a303d0 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:11.788151 25946 raft_consensus.cc:493] T 00000000000000000000000000000000 P 7bbbed38999e465db5bb4764b6a303d0 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:11.788232 25946 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 7bbbed38999e465db5bb4764b6a303d0 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:11.789067 25946 raft_consensus.cc:515] T 00000000000000000000000000000000 P 7bbbed38999e465db5bb4764b6a303d0 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7bbbed38999e465db5bb4764b6a303d0" member_type: VOTER }
I20260812 06:17:11.789458 25946 leader_election.cc:304] T 00000000000000000000000000000000 P 7bbbed38999e465db5bb4764b6a303d0 [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: 7bbbed38999e465db5bb4764b6a303d0; no voters: 
I20260812 06:17:11.789731 25946 leader_election.cc:290] T 00000000000000000000000000000000 P 7bbbed38999e465db5bb4764b6a303d0 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:11.789886 25949 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 7bbbed38999e465db5bb4764b6a303d0 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:11.790181 25949 raft_consensus.cc:697] T 00000000000000000000000000000000 P 7bbbed38999e465db5bb4764b6a303d0 [term 1 LEADER]: Becoming Leader. State: Replica: 7bbbed38999e465db5bb4764b6a303d0, State: Running, Role: LEADER
I20260812 06:17:11.790627 25949 consensus_queue.cc:237] T 00000000000000000000000000000000 P 7bbbed38999e465db5bb4764b6a303d0 [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: "7bbbed38999e465db5bb4764b6a303d0" member_type: VOTER }
I20260812 06:17:11.790824 25946 sys_catalog.cc:565] T 00000000000000000000000000000000 P 7bbbed38999e465db5bb4764b6a303d0 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:11.792553 25951 sys_catalog.cc:455] T 00000000000000000000000000000000 P 7bbbed38999e465db5bb4764b6a303d0 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 7bbbed38999e465db5bb4764b6a303d0. Latest consensus state: current_term: 1 leader_uuid: "7bbbed38999e465db5bb4764b6a303d0" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7bbbed38999e465db5bb4764b6a303d0" member_type: VOTER } }
I20260812 06:17:11.792562 25950 sys_catalog.cc:455] T 00000000000000000000000000000000 P 7bbbed38999e465db5bb4764b6a303d0 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "7bbbed38999e465db5bb4764b6a303d0" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7bbbed38999e465db5bb4764b6a303d0" member_type: VOTER } }
I20260812 06:17:11.792696 25951 sys_catalog.cc:458] T 00000000000000000000000000000000 P 7bbbed38999e465db5bb4764b6a303d0 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:11.792727 25950 sys_catalog.cc:458] T 00000000000000000000000000000000 P 7bbbed38999e465db5bb4764b6a303d0 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:11.793069 25969 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:11.795617 25969 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:11.795955 25840 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:11.800174 25969 catalog_manager.cc:1383] Generated new cluster ID: f90ed5ce488144d688ac914ce8028af9
I20260812 06:17:11.800239 25969 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:11.816437 25969 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:11.817333 25969 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:11.826646 25969 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 7bbbed38999e465db5bb4764b6a303d0: Generated new TSK 0
I20260812 06:17:11.827289 25969 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:11.860929 25840 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:11.864017 25986 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:11.864069 25988 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:11.864030 25985 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:11.864244 25840 server_base.cc:1061] running on GCE node
I20260812 06:17:11.864531 25840 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:11.864614 25840 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:11.864651 25840 hybrid_clock.cc:648] HybridClock initialized: now 1786515431864650 us; error 0 us; skew 500 ppm
I20260812 06:17:11.865648 25840 webserver.cc:533] Webserver started at http://127.25.60.1:34371/ using document root <none> and password file <none>
I20260812 06:17:11.865828 25840 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:11.865901 25840 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:11.865983 25840 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:11.866375 25840 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root/instance:
uuid: "3fad348cfd2e46488542512b30d4f9bc"
format_stamp: "Formatted at 2026-08-12 06:17:11 on dist-test-slave-44d2"
I20260812 06:17:11.867938 25840 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:11.868997 25993 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:11.869302 25840 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.000s
I20260812 06:17:11.869376 25840 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root
uuid: "3fad348cfd2e46488542512b30d4f9bc"
format_stamp: "Formatted at 2026-08-12 06:17:11 on dist-test-slave-44d2"
I20260812 06:17:11.869465 25840 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:11.876363 25840 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:11.876808 25840 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:11.877306 25840 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:11.878185 25840 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:11.878237 25840 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:11.878304 25840 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:11.878343 25840 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:11.885114 25840 rpc_server.cc:307] RPC server started. Bound to: 127.25.60.1:44627
I20260812 06:17:11.885151 26096 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.60.1:44627 every 8 connection(s)
I20260812 06:17:11.895701 26097 heartbeater.cc:344] Connected to a master server at 127.25.60.62:33853
I20260812 06:17:11.895964 26097 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:11.896454 26097 heartbeater.cc:507] Master 127.25.60.62:33853 requested a full tablet report, sending...
I20260812 06:17:11.898015 25889 ts_manager.cc:194] Registered new tserver with Master: 3fad348cfd2e46488542512b30d4f9bc (127.25.60.1:44627)
I20260812 06:17:11.898068 25840 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012360661s
I20260812 06:17:11.899497 25889 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:49230
I20260812 06:17:11.907652 25889 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:49242:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:11.922545 26045 tablet_service.cc:1511] Processing CreateTablet for tablet bd6b67fa617441d385c1e450c7896ef1 (DEFAULT_TABLE table=heavy-update-compaction-test [id=86f4558abb4f405db071a472e9df2985]), partition=
I20260812 06:17:11.923067 26045 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet bd6b67fa617441d385c1e450c7896ef1. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:11.925640 26112 tablet_bootstrap.cc:492] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Bootstrap starting.
I20260812 06:17:11.927160 26112 tablet_bootstrap.cc:654] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:11.928284 26112 tablet_bootstrap.cc:492] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: No bootstrap required, opened a new log
I20260812 06:17:11.928373 26112 ts_tablet_manager.cc:1403] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:11.928879 26112 raft_consensus.cc:359] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3fad348cfd2e46488542512b30d4f9bc" member_type: VOTER last_known_addr { host: "127.25.60.1" port: 44627 } }
I20260812 06:17:11.928985 26112 raft_consensus.cc:385] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:11.929008 26112 raft_consensus.cc:740] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 3fad348cfd2e46488542512b30d4f9bc, State: Initialized, Role: FOLLOWER
I20260812 06:17:11.929159 26112 consensus_queue.cc:260] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc [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: "3fad348cfd2e46488542512b30d4f9bc" member_type: VOTER last_known_addr { host: "127.25.60.1" port: 44627 } }
I20260812 06:17:11.929250 26112 raft_consensus.cc:399] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:11.929327 26112 raft_consensus.cc:493] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:11.929388 26112 raft_consensus.cc:3060] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:11.930198 26112 raft_consensus.cc:515] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3fad348cfd2e46488542512b30d4f9bc" member_type: VOTER last_known_addr { host: "127.25.60.1" port: 44627 } }
I20260812 06:17:11.930374 26112 leader_election.cc:304] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc [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: 3fad348cfd2e46488542512b30d4f9bc; no voters: 
I20260812 06:17:11.930631 26112 leader_election.cc:290] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:11.931016 26114 raft_consensus.cc:2804] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:11.931159 26112 ts_tablet_manager.cc:1434] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:11.931273 26114 raft_consensus.cc:697] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc [term 1 LEADER]: Becoming Leader. State: Replica: 3fad348cfd2e46488542512b30d4f9bc, State: Running, Role: LEADER
I20260812 06:17:11.931331 26097 heartbeater.cc:499] Master 127.25.60.62:33853 was elected leader, sending a full tablet report...
I20260812 06:17:11.931473 26114 consensus_queue.cc:237] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc [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: "3fad348cfd2e46488542512b30d4f9bc" member_type: VOTER last_known_addr { host: "127.25.60.1" port: 44627 } }
I20260812 06:17:11.934314 25889 catalog_manager.cc:5719] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc reported cstate change: term changed from 0 to 1, leader changed from <none> to 3fad348cfd2e46488542512b30d4f9bc (127.25.60.1). New cstate: current_term: 1 leader_uuid: "3fad348cfd2e46488542512b30d4f9bc" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3fad348cfd2e46488542512b30d4f9bc" member_type: VOTER last_known_addr { host: "127.25.60.1" port: 44627 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:12.006539 25840 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.063s	user 0.015s	sys 0.012s
I20260812 06:17:12.136457 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushMRSOp(bd6b67fa617441d385c1e450c7896ef1): perf score=15.086190
I20260812 06:17:12.308267 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushMRSOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.171s	user 0.105s	sys 0.057s Metrics: {"bytes_written":13702312,"cfile_init":1,"compiler_manager_pool.queue_time_us":219,"delete_count":0,"dirs.queue_time_us":38,"dirs.run_cpu_time_us":280,"dirs.run_wall_time_us":1117,"drs_written":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42987,"lbm_writes_lt_1ms":701,"mutex_wait_us":3064,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":154496,"thread_start_us":150,"threads_started":1,"update_count":1670}
I20260812 06:17:12.309540 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=2.188937
I20260812 06:17:12.325294 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":3446263,"delete_count":0,"lbm_write_time_us":5548,"lbm_writes_lt_1ms":87,"reinsert_count":0,"update_count":420}
I20260812 06:17:12.325850 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling LogGCOp(bd6b67fa617441d385c1e450c7896ef1): free 20743880 bytes of WAL
I20260812 06:17:12.326148 26005 log_reader.cc:385] T bd6b67fa617441d385c1e450c7896ef1: removed 2 log segments from log reader
I20260812 06:17:12.326208 26005 log.cc:1079] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/bd6b67fa617441d385c1e450c7896ef1/wal-000000001 (ops 1-6)
I20260812 06:17:12.326263 26005 log.cc:1079] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/bd6b67fa617441d385c1e450c7896ef1/wal-000000002 (ops 7-11)
I20260812 06:17:12.332409 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: LogGCOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:12.332753 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=1.196750
I20260812 06:17:12.340930 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.008s	user 0.006s	sys 0.001s Metrics: {"bytes_written":2953955,"delete_count":0,"lbm_write_time_us":2979,"lbm_writes_lt_1ms":75,"reinsert_count":0,"update_count":360}
I20260812 06:17:12.341369 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling MajorDeltaCompactionOp(bd6b67fa617441d385c1e450c7896ef1): perf score=1.000000
I20260812 06:17:12.514473 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: MajorDeltaCompactionOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.173s	user 0.125s	sys 0.044s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24364530,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":688,"lbm_read_time_us":12164,"lbm_reads_lt_1ms":563,"lbm_write_time_us":29105,"lbm_writes_lt_1ms":533,"mutex_wait_us":23,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":8064,"thread_start_us":374,"threads_started":5,"update_count":2450}
I20260812 06:17:12.515137 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling UndoDeltaBlockGCOp(bd6b67fa617441d385c1e450c7896ef1): 12719216 bytes on disk
I20260812 06:17:12.515655 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: UndoDeltaBlockGCOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4}
I20260812 06:17:12.516101 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=10.126437
I20260812 06:17:12.556264 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.040s	user 0.010s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13944,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:12.556989 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=2.188937
I20260812 06:17:12.568212 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4296,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.568750 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling MajorDeltaCompactionOp(bd6b67fa617441d385c1e450c7896ef1): perf score=1.000000
I20260812 06:17:12.712738 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: MajorDeltaCompactionOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.144s	user 0.112s	sys 0.028s 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":719,"lbm_read_time_us":9909,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27345,"lbm_writes_lt_1ms":443,"mutex_wait_us":278,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1152,"update_count":2000}
I20260812 06:17:12.713579 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=10.126437
I20260812 06:17:12.755859 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.042s	user 0.022s	sys 0.009s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14399,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:12.756343 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=2.188937
I20260812 06:17:12.767333 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3991,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.767830 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling MajorDeltaCompactionOp(bd6b67fa617441d385c1e450c7896ef1): perf score=1.000000
I20260812 06:17:12.897135 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: MajorDeltaCompactionOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.129s	user 0.093s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":535,"lbm_read_time_us":9150,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24346,"lbm_writes_lt_1ms":443,"mutex_wait_us":310,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:12.898128 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=10.126437
I20260812 06:17:12.946363 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.047s	user 0.011s	sys 0.034s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16662,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:12.946941 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=2.188937
I20260812 06:17:12.958465 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4477,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.959017 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling MajorDeltaCompactionOp(bd6b67fa617441d385c1e450c7896ef1): perf score=1.000000
I20260812 06:17:13.102136 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: MajorDeltaCompactionOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.143s	user 0.103s	sys 0.040s 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":254,"lbm_read_time_us":11029,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23561,"lbm_writes_lt_1ms":443,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:13.102734 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=10.126437
I20260812 06:17:13.146183 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.043s	user 0.009s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15469,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:13.146653 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=2.188937
I20260812 06:17:13.157397 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4236,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.157883 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling MajorDeltaCompactionOp(bd6b67fa617441d385c1e450c7896ef1): perf score=1.000000
I20260812 06:17:13.283165 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: MajorDeltaCompactionOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.125s	user 0.075s	sys 0.050s 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":852,"lbm_read_time_us":8997,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24158,"lbm_writes_lt_1ms":443,"mutex_wait_us":55,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":2000}
I20260812 06:17:13.283896 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=10.126437
I20260812 06:17:13.336975 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.053s	user 0.028s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":23795,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:17:13.337524 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=2.188937
I20260812 06:17:13.348749 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.011s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3981,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.349411 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling MajorDeltaCompactionOp(bd6b67fa617441d385c1e450c7896ef1): perf score=1.000000
I20260812 06:17:13.477244 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: MajorDeltaCompactionOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.128s	user 0.107s	sys 0.020s 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":391,"lbm_read_time_us":8715,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25245,"lbm_writes_lt_1ms":443,"mutex_wait_us":67,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:13.477840 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=10.126437
I20260812 06:17:13.534464 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.056s	user 0.018s	sys 0.026s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16009,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:13.535043 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=2.188937
I20260812 06:17:13.552052 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.017s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6074,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.552736 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushMRSOp(bd6b67fa617441d385c1e450c7896ef1): perf score=1.000000
I20260812 06:17:13.590873 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushMRSOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.038s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":336,"dirs.run_wall_time_us":1471,"drs_written":1,"lbm_read_time_us":91,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1603,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:13.591809 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling LogGCOp(bd6b67fa617441d385c1e450c7896ef1): free 111786278 bytes of WAL
I20260812 06:17:13.592126 26005 log_reader.cc:385] T bd6b67fa617441d385c1e450c7896ef1: removed 11 log segments from log reader
I20260812 06:17:13.592226 26005 log.cc:1079] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/bd6b67fa617441d385c1e450c7896ef1/wal-000000003 (ops 12-16)
I20260812 06:17:13.592276 26005 log.cc:1079] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/bd6b67fa617441d385c1e450c7896ef1/wal-000000004 (ops 17-20)
I20260812 06:17:13.592320 26005 log.cc:1079] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/bd6b67fa617441d385c1e450c7896ef1/wal-000000005 (ops 21-25)
I20260812 06:17:13.592361 26005 log.cc:1079] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/bd6b67fa617441d385c1e450c7896ef1/wal-000000006 (ops 26-30)
I20260812 06:17:13.592392 26005 log.cc:1079] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/bd6b67fa617441d385c1e450c7896ef1/wal-000000007 (ops 31-35)
I20260812 06:17:13.592427 26005 log.cc:1079] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/bd6b67fa617441d385c1e450c7896ef1/wal-000000008 (ops 36-40)
I20260812 06:17:13.592465 26005 log.cc:1079] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/bd6b67fa617441d385c1e450c7896ef1/wal-000000009 (ops 41-45)
I20260812 06:17:13.592521 26005 log.cc:1079] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/bd6b67fa617441d385c1e450c7896ef1/wal-000000010 (ops 46-50)
I20260812 06:17:13.592557 26005 log.cc:1079] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/bd6b67fa617441d385c1e450c7896ef1/wal-000000011 (ops 51-54)
I20260812 06:17:13.592609 26005 log.cc:1079] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/bd6b67fa617441d385c1e450c7896ef1/wal-000000012 (ops 55-59)
I20260812 06:17:13.592649 26005 log.cc:1079] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/bd6b67fa617441d385c1e450c7896ef1/wal-000000013 (ops 60-64)
I20260812 06:17:13.617192 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: LogGCOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.025s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:17:13.617630 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=6.157687
I20260812 06:17:13.659871 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.042s	user 0.011s	sys 0.014s Metrics: {"bytes_written":8205077,"delete_count":0,"lbm_write_time_us":12107,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:13.660379 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling LogGCOp(bd6b67fa617441d385c1e450c7896ef1): free 8767067 bytes of WAL
I20260812 06:17:13.660692 26005 log_reader.cc:385] T bd6b67fa617441d385c1e450c7896ef1: removed 1 log segments from log reader
I20260812 06:17:13.660744 26005 log.cc:1079] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/bd6b67fa617441d385c1e450c7896ef1/wal-000000014 (ops 65-69)
I20260812 06:17:13.662688 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: LogGCOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:13.663062 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling UndoDeltaBlockGCOp(bd6b67fa617441d385c1e450c7896ef1): 462 bytes on disk
I20260812 06:17:13.663551 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: UndoDeltaBlockGCOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4}
I20260812 06:17:13.664033 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=2.188937
I20260812 06:17:13.678926 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5828,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.679644 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling MajorDeltaCompactionOp(bd6b67fa617441d385c1e450c7896ef1): perf score=1.000000
I20260812 06:17:13.900704 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: MajorDeltaCompactionOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.221s	user 0.143s	sys 0.077s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979751,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":263,"lbm_read_time_us":16342,"lbm_reads_lt_1ms":766,"lbm_write_time_us":40856,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":79,"threads_started":1,"update_count":3500}
I20260812 06:17:13.901350 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=14.095187
I20260812 06:17:13.953692 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.052s	user 0.024s	sys 0.025s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21625,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:13.954311 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=3.181125
I20260812 06:17:13.971755 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.017s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4547,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:13.972301 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=2.188937
I20260812 06:17:13.982494 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3575,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:13.983079 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling MajorDeltaCompactionOp(bd6b67fa617441d385c1e450c7896ef1): perf score=1.000000
I20260812 06:17:14.155652 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: MajorDeltaCompactionOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.172s	user 0.117s	sys 0.055s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877211,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":893,"lbm_read_time_us":13224,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33579,"lbm_writes_lt_1ms":643,"mutex_wait_us":130,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":3000}
I20260812 06:17:14.156292 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=14.095187
I20260812 06:17:14.215255 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.055s	user 0.030s	sys 0.019s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":23118,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:14.215775 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=2.188937
I20260812 06:17:14.226821 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4208,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.227388 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling MajorDeltaCompactionOp(bd6b67fa617441d385c1e450c7896ef1): perf score=1.000000
I20260812 06:17:14.397581 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: MajorDeltaCompactionOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.170s	user 0.131s	sys 0.028s 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":832,"lbm_read_time_us":11555,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29943,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14080,"update_count":2500}
I20260812 06:17:14.398326 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=14.095187
I20260812 06:17:14.453114 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.055s	user 0.024s	sys 0.025s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22816,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:14.453593 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling MajorDeltaCompactionOp(bd6b67fa617441d385c1e450c7896ef1): perf score=1.000000
I20260812 06:17:14.620645 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: MajorDeltaCompactionOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.167s	user 0.104s	sys 0.050s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":144,"lbm_read_time_us":11517,"lbm_reads_lt_1ms":463,"lbm_write_time_us":26657,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":97536,"update_count":2000}
I20260812 06:17:14.621403 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=14.095187
I20260812 06:17:14.672658 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.051s	user 0.024s	sys 0.025s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21915,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:14.673238 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=2.188937
I20260812 06:17:14.689508 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.016s	user 0.009s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6217,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.690253 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling MajorDeltaCompactionOp(bd6b67fa617441d385c1e450c7896ef1): perf score=1.000000
I20260812 06:17:14.892185 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: MajorDeltaCompactionOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.202s	user 0.120s	sys 0.066s 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":2696,"lbm_read_time_us":13893,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29518,"lbm_writes_lt_1ms":543,"mutex_wait_us":2041,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":22272,"update_count":2500}
I20260812 06:17:14.892750 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=14.095187
I20260812 06:17:14.944041 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.051s	user 0.025s	sys 0.020s Metrics: {"bytes_written":16409908,"delete_count":0,"lbm_write_time_us":21785,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:14.944644 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=2.188937
I20260812 06:17:14.961650 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.017s	user 0.002s	sys 0.014s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6799,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.962533 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling MajorDeltaCompactionOp(bd6b67fa617441d385c1e450c7896ef1): perf score=1.000000
I20260812 06:17:15.118124 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: MajorDeltaCompactionOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.155s	user 0.112s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774695,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":948,"lbm_read_time_us":9442,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32763,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":541,"mutex_wait_us":277,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12800,"update_count":2500}
I20260812 06:17:15.118755 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=11.118625
I20260812 06:17:15.156004 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.037s	user 0.022s	sys 0.012s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":17092,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:15.156665 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=2.188937
I20260812 06:17:15.183667 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.027s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5197,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:15.184199 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=2.188937
I20260812 06:17:15.194839 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3873,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.195346 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushMRSOp(bd6b67fa617441d385c1e450c7896ef1): perf score=1.000000
I20260812 06:17:15.226215 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushMRSOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.031s	user 0.021s	sys 0.008s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":236,"dirs.run_wall_time_us":1400,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1777,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:15.227051 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling LogGCOp(bd6b67fa617441d385c1e450c7896ef1): free 132571381 bytes of WAL
I20260812 06:17:15.227334 26005 log_reader.cc:385] T bd6b67fa617441d385c1e450c7896ef1: removed 13 log segments from log reader
I20260812 06:17:15.227402 26005 log.cc:1079] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/bd6b67fa617441d385c1e450c7896ef1/wal-000000015 (ops 70-74)
I20260812 06:17:15.227439 26005 log.cc:1079] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/bd6b67fa617441d385c1e450c7896ef1/wal-000000016 (ops 75-79)
I20260812 06:17:15.227463 26005 log.cc:1079] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/bd6b67fa617441d385c1e450c7896ef1/wal-000000017 (ops 80-84)
I20260812 06:17:15.227487 26005 log.cc:1079] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/bd6b67fa617441d385c1e450c7896ef1/wal-000000018 (ops 85-89)
I20260812 06:17:15.227514 26005 log.cc:1079] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/bd6b67fa617441d385c1e450c7896ef1/wal-000000019 (ops 90-94)
I20260812 06:17:15.227542 26005 log.cc:1079] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/bd6b67fa617441d385c1e450c7896ef1/wal-000000020 (ops 95-99)
I20260812 06:17:15.227582 26005 log.cc:1079] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/bd6b67fa617441d385c1e450c7896ef1/wal-000000021 (ops 100-104)
I20260812 06:17:15.227605 26005 log.cc:1079] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/bd6b67fa617441d385c1e450c7896ef1/wal-000000022 (ops 105-108)
I20260812 06:17:15.227626 26005 log.cc:1079] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/bd6b67fa617441d385c1e450c7896ef1/wal-000000023 (ops 109-113)
I20260812 06:17:15.227659 26005 log.cc:1079] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/bd6b67fa617441d385c1e450c7896ef1/wal-000000024 (ops 114-118)
I20260812 06:17:15.227690 26005 log.cc:1079] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/bd6b67fa617441d385c1e450c7896ef1/wal-000000025 (ops 119-123)
I20260812 06:17:15.227717 26005 log.cc:1079] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/bd6b67fa617441d385c1e450c7896ef1/wal-000000026 (ops 124-128)
I20260812 06:17:15.227758 26005 log.cc:1079] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/bd6b67fa617441d385c1e450c7896ef1/wal-000000027 (ops 129-132)
I20260812 06:17:15.262122 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: LogGCOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.035s	user 0.000s	sys 0.033s Metrics: {}
I20260812 06:17:15.262694 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling UndoDeltaBlockGCOp(bd6b67fa617441d385c1e450c7896ef1): 493 bytes on disk
I20260812 06:17:15.263489 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: UndoDeltaBlockGCOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":137,"lbm_reads_lt_1ms":4}
I20260812 06:17:15.264206 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=2.188937
I20260812 06:17:15.295159 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.031s	user 0.007s	sys 0.021s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6427,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.295842 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=2.188937
I20260812 06:17:15.307652 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4675,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.308214 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling MajorDeltaCompactionOp(bd6b67fa617441d385c1e450c7896ef1): perf score=1.000000
I20260812 06:17:15.540958 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: MajorDeltaCompactionOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.233s	user 0.176s	sys 0.056s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979858,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":668,"lbm_read_time_us":16841,"lbm_reads_lt_1ms":775,"lbm_write_time_us":41568,"lbm_writes_lt_1ms":743,"mutex_wait_us":368,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":9984,"thread_start_us":84,"threads_started":1,"update_count":3500}
I20260812 06:17:15.541817 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=14.095187
I20260812 06:17:15.609298 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.067s	user 0.036s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20086,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:15.610294 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=2.188937
I20260812 06:17:15.630722 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.020s	user 0.010s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7689,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.631299 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling MajorDeltaCompactionOp(bd6b67fa617441d385c1e450c7896ef1): perf score=1.000000
I20260812 06:17:15.828117 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: MajorDeltaCompactionOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.197s	user 0.140s	sys 0.050s 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":889,"lbm_read_time_us":15791,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30973,"lbm_writes_lt_1ms":543,"mutex_wait_us":276,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:15.828836 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=14.095187
I20260812 06:17:15.892210 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.063s	user 0.020s	sys 0.034s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20359,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:15.892880 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=2.188937
I20260812 06:17:15.909736 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.017s	user 0.013s	sys 0.002s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6204,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.910351 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling MajorDeltaCompactionOp(bd6b67fa617441d385c1e450c7896ef1): perf score=1.000000
I20260812 06:17:16.109011 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: MajorDeltaCompactionOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.198s	user 0.125s	sys 0.072s 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":465,"lbm_read_time_us":16070,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33959,"lbm_writes_lt_1ms":543,"mutex_wait_us":74,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:17:16.109786 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=14.095187
I20260812 06:17:16.166996 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.057s	user 0.043s	sys 0.004s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22211,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:16.167608 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=2.188937
I20260812 06:17:16.186795 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.019s	user 0.010s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4147,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.187405 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling MajorDeltaCompactionOp(bd6b67fa617441d385c1e450c7896ef1): perf score=1.000000
I20260812 06:17:16.388865 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: MajorDeltaCompactionOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.201s	user 0.138s	sys 0.063s 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":169,"lbm_read_time_us":14339,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35153,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:16.389560 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=14.095187
I20260812 06:17:16.450388 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.061s	user 0.043s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":27269,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:16.451009 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=2.188937
I20260812 06:17:16.492873 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.042s	user 0.022s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7288,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":500}
I20260812 06:17:16.493554 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=2.188937
I20260812 06:17:16.510511 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.017s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6393,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.511210 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling MajorDeltaCompactionOp(bd6b67fa617441d385c1e450c7896ef1): perf score=1.000000
I20260812 06:17:16.727758 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: MajorDeltaCompactionOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.216s	user 0.136s	sys 0.076s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877220,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":308,"lbm_read_time_us":16669,"lbm_reads_lt_1ms":673,"lbm_write_time_us":36470,"lbm_writes_lt_1ms":643,"mutex_wait_us":51,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":3000}
I20260812 06:17:16.728531 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=14.095187
I20260812 06:17:16.790884 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.062s	user 0.025s	sys 0.032s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22697,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:16.791524 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=2.188937
I20260812 06:17:16.803095 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4500,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.803591 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushMRSOp(bd6b67fa617441d385c1e450c7896ef1): perf score=1.000000
I20260812 06:17:16.844883 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushMRSOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.041s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":238,"dirs.run_wall_time_us":1374,"drs_written":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1501,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:16.845652 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling LogGCOp(bd6b67fa617441d385c1e450c7896ef1): free 108535684 bytes of WAL
I20260812 06:17:16.845888 26005 log_reader.cc:385] T bd6b67fa617441d385c1e450c7896ef1: removed 11 log segments from log reader
I20260812 06:17:16.845942 26005 log.cc:1079] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/bd6b67fa617441d385c1e450c7896ef1/wal-000000028 (ops 133-137)
I20260812 06:17:16.845997 26005 log.cc:1079] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/bd6b67fa617441d385c1e450c7896ef1/wal-000000029 (ops 138-142)
I20260812 06:17:16.846045 26005 log.cc:1079] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/bd6b67fa617441d385c1e450c7896ef1/wal-000000030 (ops 143-147)
I20260812 06:17:16.846076 26005 log.cc:1079] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/bd6b67fa617441d385c1e450c7896ef1/wal-000000031 (ops 148-152)
I20260812 06:17:16.846117 26005 log.cc:1079] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/bd6b67fa617441d385c1e450c7896ef1/wal-000000032 (ops 153-156)
I20260812 06:17:16.846158 26005 log.cc:1079] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/bd6b67fa617441d385c1e450c7896ef1/wal-000000033 (ops 157-161)
I20260812 06:17:16.846197 26005 log.cc:1079] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/bd6b67fa617441d385c1e450c7896ef1/wal-000000034 (ops 162-166)
I20260812 06:17:16.846238 26005 log.cc:1079] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/bd6b67fa617441d385c1e450c7896ef1/wal-000000035 (ops 167-170)
I20260812 06:17:16.846277 26005 log.cc:1079] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/bd6b67fa617441d385c1e450c7896ef1/wal-000000036 (ops 171-175)
I20260812 06:17:16.846320 26005 log.cc:1079] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/bd6b67fa617441d385c1e450c7896ef1/wal-000000037 (ops 176-180)
I20260812 06:17:16.846356 26005 log.cc:1079] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/bd6b67fa617441d385c1e450c7896ef1/wal-000000038 (ops 181-185)
I20260812 06:17:16.870810 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: LogGCOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.025s	user 0.001s	sys 0.022s Metrics: {}
I20260812 06:17:16.871243 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=3.181125
I20260812 06:17:16.890415 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.019s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4493,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:16.890908 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling UndoDeltaBlockGCOp(bd6b67fa617441d385c1e450c7896ef1): 447 bytes on disk
I20260812 06:17:16.891338 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: UndoDeltaBlockGCOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:17:16.891878 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=2.188937
I20260812 06:17:16.902165 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3742,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:16.902697 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling MajorDeltaCompactionOp(bd6b67fa617441d385c1e450c7896ef1): perf score=1.000000
I20260812 06:17:17.124024 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: MajorDeltaCompactionOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.221s	user 0.124s	sys 0.095s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979742,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":694,"lbm_read_time_us":15665,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39627,"lbm_writes_lt_1ms":743,"mutex_wait_us":89,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":12416,"thread_start_us":88,"threads_started":1,"update_count":3500}
I20260812 06:17:17.125389 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=14.095187
I20260812 06:17:17.159741 25840 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.153s	user 1.910s	sys 0.141s
I20260812 06:17:17.176391 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.051s	user 0.023s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24023,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:17.177057 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1): perf score=2.188937
I20260812 06:17:17.186861 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: FlushDeltaMemStoresOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3987,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.187492 26098 maintenance_manager.cc:419] P 3fad348cfd2e46488542512b30d4f9bc: Scheduling MajorDeltaCompactionOp(bd6b67fa617441d385c1e450c7896ef1): perf score=1.000000
I20260812 06:17:17.207335 25840 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.047s	user 0.002s	sys 0.000s
I20260812 06:17:17.208020 25840 tablet_server.cc:179] TabletServer@127.25.60.1:0 shutting down...
I20260812 06:17:17.345585 26005 maintenance_manager.cc:643] P 3fad348cfd2e46488542512b30d4f9bc: MajorDeltaCompactionOp(bd6b67fa617441d385c1e450c7896ef1) complete. Timing: real 0.158s	user 0.121s	sys 0.035s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4262390,"cfile_cache_miss":502,"cfile_cache_miss_bytes":20512299,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":702,"lbm_read_time_us":8757,"lbm_reads_lt_1ms":518,"lbm_write_time_us":29513,"lbm_writes_lt_1ms":543,"mutex_wait_us":330,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:17.346367 25840 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:17.346779 25840 tablet_replica.cc:333] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc: stopping tablet replica
I20260812 06:17:17.347087 25840 raft_consensus.cc:2243] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:17.347359 25840 raft_consensus.cc:2272] T bd6b67fa617441d385c1e450c7896ef1 P 3fad348cfd2e46488542512b30d4f9bc [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:17.363221 25840 tablet_server.cc:196] TabletServer@127.25.60.1:0 shutdown complete.
I20260812 06:17:17.396190 25840 master.cc:562] Master@127.25.60.62:33853 shutting down...
I20260812 06:17:17.400051 25840 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 7bbbed38999e465db5bb4764b6a303d0 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:17.400229 25840 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 7bbbed38999e465db5bb4764b6a303d0 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:17.400285 25840 tablet_replica.cc:333] T 00000000000000000000000000000000 P 7bbbed38999e465db5bb4764b6a303d0: stopping tablet replica
I20260812 06:17:17.412760 25840 master.cc:584] Master@127.25.60.62:33853 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5786 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:17.504779 25840 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.25.60.62:45037
I20260812 06:17:17.505213 25840 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:17.507570 26146 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:17.507606 25840 server_base.cc:1061] running on GCE node
W20260812 06:17:17.507751 26143 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:17.507607 26142 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:17.508071 25840 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:17.508140 25840 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:17.508164 25840 hybrid_clock.cc:648] HybridClock initialized: now 1786515437508164 us; error 0 us; skew 500 ppm
I20260812 06:17:17.509127 25840 webserver.cc:533] Webserver started at http://127.25.60.62:37935/ using document root <none> and password file <none>
I20260812 06:17:17.509303 25840 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:17.509371 25840 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:17.509451 25840 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:17.509847 25840 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/master-0-root/instance:
uuid: "dc26d86fd045405c996030df9a006305"
format_stamp: "Formatted at 2026-08-12 06:17:17 on dist-test-slave-44d2"
I20260812 06:17:17.511420 25840 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:17.512349 26152 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:17.512643 25840 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:17.512737 25840 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/master-0-root
uuid: "dc26d86fd045405c996030df9a006305"
format_stamp: "Formatted at 2026-08-12 06:17:17 on dist-test-slave-44d2"
I20260812 06:17:17.512828 25840 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:17.528213 25840 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:17.528713 25840 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:17.532927 25840 rpc_server.cc:307] RPC server started. Bound to: 127.25.60.62:45037
I20260812 06:17:17.536403 26241 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.60.62:45037 every 8 connection(s)
I20260812 06:17:17.551426 26243 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:17.553678 26243 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P dc26d86fd045405c996030df9a006305: Bootstrap starting.
I20260812 06:17:17.554560 26243 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P dc26d86fd045405c996030df9a006305: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:17.555732 26243 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P dc26d86fd045405c996030df9a006305: No bootstrap required, opened a new log
I20260812 06:17:17.556211 26243 raft_consensus.cc:359] T 00000000000000000000000000000000 P dc26d86fd045405c996030df9a006305 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "dc26d86fd045405c996030df9a006305" member_type: VOTER }
I20260812 06:17:17.556301 26243 raft_consensus.cc:385] T 00000000000000000000000000000000 P dc26d86fd045405c996030df9a006305 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:17.556324 26243 raft_consensus.cc:740] T 00000000000000000000000000000000 P dc26d86fd045405c996030df9a006305 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: dc26d86fd045405c996030df9a006305, State: Initialized, Role: FOLLOWER
I20260812 06:17:17.556567 26243 consensus_queue.cc:260] T 00000000000000000000000000000000 P dc26d86fd045405c996030df9a006305 [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: "dc26d86fd045405c996030df9a006305" member_type: VOTER }
I20260812 06:17:17.556651 26243 raft_consensus.cc:399] T 00000000000000000000000000000000 P dc26d86fd045405c996030df9a006305 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:17.556699 26243 raft_consensus.cc:493] T 00000000000000000000000000000000 P dc26d86fd045405c996030df9a006305 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:17.556763 26243 raft_consensus.cc:3060] T 00000000000000000000000000000000 P dc26d86fd045405c996030df9a006305 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:17.557471 26243 raft_consensus.cc:515] T 00000000000000000000000000000000 P dc26d86fd045405c996030df9a006305 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "dc26d86fd045405c996030df9a006305" member_type: VOTER }
I20260812 06:17:17.557624 26243 leader_election.cc:304] T 00000000000000000000000000000000 P dc26d86fd045405c996030df9a006305 [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: dc26d86fd045405c996030df9a006305; no voters: 
I20260812 06:17:17.557860 26243 leader_election.cc:290] T 00000000000000000000000000000000 P dc26d86fd045405c996030df9a006305 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:17.558004 26250 raft_consensus.cc:2804] T 00000000000000000000000000000000 P dc26d86fd045405c996030df9a006305 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:17.558246 26250 raft_consensus.cc:697] T 00000000000000000000000000000000 P dc26d86fd045405c996030df9a006305 [term 1 LEADER]: Becoming Leader. State: Replica: dc26d86fd045405c996030df9a006305, State: Running, Role: LEADER
I20260812 06:17:17.558445 26250 consensus_queue.cc:237] T 00000000000000000000000000000000 P dc26d86fd045405c996030df9a006305 [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: "dc26d86fd045405c996030df9a006305" member_type: VOTER }
I20260812 06:17:17.558480 26243 sys_catalog.cc:565] T 00000000000000000000000000000000 P dc26d86fd045405c996030df9a006305 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:17.558956 26253 sys_catalog.cc:455] T 00000000000000000000000000000000 P dc26d86fd045405c996030df9a006305 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "dc26d86fd045405c996030df9a006305" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "dc26d86fd045405c996030df9a006305" member_type: VOTER } }
I20260812 06:17:17.558987 26255 sys_catalog.cc:455] T 00000000000000000000000000000000 P dc26d86fd045405c996030df9a006305 [sys.catalog]: SysCatalogTable state changed. Reason: New leader dc26d86fd045405c996030df9a006305. Latest consensus state: current_term: 1 leader_uuid: "dc26d86fd045405c996030df9a006305" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "dc26d86fd045405c996030df9a006305" member_type: VOTER } }
I20260812 06:17:17.559047 26253 sys_catalog.cc:458] T 00000000000000000000000000000000 P dc26d86fd045405c996030df9a006305 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:17.559074 26255 sys_catalog.cc:458] T 00000000000000000000000000000000 P dc26d86fd045405c996030df9a006305 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:17.559706 26259 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:17.560773 26259 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:17.560985 25840 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:17.562623 26259 catalog_manager.cc:1383] Generated new cluster ID: 68f740a4ba6a48f4850733194934b5b8
I20260812 06:17:17.562683 26259 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:17.582353 26259 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:17.582949 26259 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:17.594304 26259 catalog_manager.cc:6092] T 00000000000000000000000000000000 P dc26d86fd045405c996030df9a006305: Generated new TSK 0
I20260812 06:17:17.594518 26259 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:17.625675 25840 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:17.627828 26282 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:17.627905 26276 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:17.627900 26278 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:17.628175 25840 server_base.cc:1061] running on GCE node
I20260812 06:17:17.628365 25840 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:17.628404 25840 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:17.628420 25840 hybrid_clock.cc:648] HybridClock initialized: now 1786515437628420 us; error 0 us; skew 500 ppm
I20260812 06:17:17.631166 25840 webserver.cc:533] Webserver started at http://127.25.60.1:46385/ using document root <none> and password file <none>
I20260812 06:17:17.631311 25840 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:17.631358 25840 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:17.631414 25840 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:17.631776 25840 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/instance:
uuid: "3f1c56bee3f3443197fe1f19dd2bb1e0"
format_stamp: "Formatted at 2026-08-12 06:17:17 on dist-test-slave-44d2"
I20260812 06:17:17.633313 25840 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:17.634284 26289 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:17.634577 25840 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:17.634644 25840 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root
uuid: "3f1c56bee3f3443197fe1f19dd2bb1e0"
format_stamp: "Formatted at 2026-08-12 06:17:17 on dist-test-slave-44d2"
I20260812 06:17:17.634738 25840 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:17.654073 25840 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:17.654506 25840 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:17.654848 25840 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:17.655391 25840 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:17.655462 25840 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:17.655521 25840 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:17.655573 25840 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:17.660450 25840 rpc_server.cc:307] RPC server started. Bound to: 127.25.60.1:44063
I20260812 06:17:17.660522 26390 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.60.1:44063 every 8 connection(s)
I20260812 06:17:17.668891 26391 heartbeater.cc:344] Connected to a master server at 127.25.60.62:45037
I20260812 06:17:17.669023 26391 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:17.669261 26391 heartbeater.cc:507] Master 127.25.60.62:45037 requested a full tablet report, sending...
I20260812 06:17:17.669988 26187 ts_manager.cc:194] Registered new tserver with Master: 3f1c56bee3f3443197fe1f19dd2bb1e0 (127.25.60.1:44063)
I20260812 06:17:17.670725 26187 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:58662
I20260812 06:17:17.671010 25840 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.010076459s
I20260812 06:17:17.678095 26187 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:58666:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:17.686676 26337 tablet_service.cc:1511] Processing CreateTablet for tablet f389340cb0f04ed08b26acb6373f6b4c (DEFAULT_TABLE table=heavy-update-compaction-test [id=d476ddcafcc248b2b65ee564cbd3e976]), partition=
I20260812 06:17:17.686971 26337 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet f389340cb0f04ed08b26acb6373f6b4c. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:17.688968 26407 tablet_bootstrap.cc:492] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Bootstrap starting.
I20260812 06:17:17.689996 26407 tablet_bootstrap.cc:654] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:17.691051 26407 tablet_bootstrap.cc:492] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: No bootstrap required, opened a new log
I20260812 06:17:17.691190 26407 ts_tablet_manager.cc:1403] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:17.691605 26407 raft_consensus.cc:359] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3f1c56bee3f3443197fe1f19dd2bb1e0" member_type: VOTER last_known_addr { host: "127.25.60.1" port: 44063 } }
I20260812 06:17:17.691713 26407 raft_consensus.cc:385] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:17.691762 26407 raft_consensus.cc:740] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 3f1c56bee3f3443197fe1f19dd2bb1e0, State: Initialized, Role: FOLLOWER
I20260812 06:17:17.691928 26407 consensus_queue.cc:260] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0 [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: "3f1c56bee3f3443197fe1f19dd2bb1e0" member_type: VOTER last_known_addr { host: "127.25.60.1" port: 44063 } }
I20260812 06:17:17.692042 26407 raft_consensus.cc:399] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:17.692094 26407 raft_consensus.cc:493] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:17.692147 26407 raft_consensus.cc:3060] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:17.693084 26407 raft_consensus.cc:515] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3f1c56bee3f3443197fe1f19dd2bb1e0" member_type: VOTER last_known_addr { host: "127.25.60.1" port: 44063 } }
I20260812 06:17:17.693267 26407 leader_election.cc:304] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0 [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: 3f1c56bee3f3443197fe1f19dd2bb1e0; no voters: 
I20260812 06:17:17.693485 26407 leader_election.cc:290] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:17.693624 26412 raft_consensus.cc:2804] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:17.693835 26407 ts_tablet_manager.cc:1434] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:17.693852 26391 heartbeater.cc:499] Master 127.25.60.62:45037 was elected leader, sending a full tablet report...
I20260812 06:17:17.693852 26412 raft_consensus.cc:697] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0 [term 1 LEADER]: Becoming Leader. State: Replica: 3f1c56bee3f3443197fe1f19dd2bb1e0, State: Running, Role: LEADER
I20260812 06:17:17.694059 26412 consensus_queue.cc:237] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0 [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: "3f1c56bee3f3443197fe1f19dd2bb1e0" member_type: VOTER last_known_addr { host: "127.25.60.1" port: 44063 } }
I20260812 06:17:17.695295 26187 catalog_manager.cc:5719] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0 reported cstate change: term changed from 0 to 1, leader changed from <none> to 3f1c56bee3f3443197fe1f19dd2bb1e0 (127.25.60.1). New cstate: current_term: 1 leader_uuid: "3f1c56bee3f3443197fe1f19dd2bb1e0" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3f1c56bee3f3443197fe1f19dd2bb1e0" member_type: VOTER last_known_addr { host: "127.25.60.1" port: 44063 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:17.757802 25840 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.018s	sys 0.004s
I20260812 06:17:17.911594 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushMRSOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=19.054940
I20260812 06:17:18.090550 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushMRSOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.179s	user 0.137s	sys 0.039s Metrics: {"bytes_written":13168992,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":243,"dirs.run_wall_time_us":877,"drs_written":1,"lbm_read_time_us":101,"lbm_reads_lt_1ms":4,"lbm_write_time_us":47769,"lbm_writes_lt_1ms":778,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":896,"update_count":1605}
I20260812 06:17:18.091214 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling LogGCOp(f389340cb0f04ed08b26acb6373f6b4c): free 20743831 bytes of WAL
I20260812 06:17:18.091473 26296 log_reader.cc:385] T f389340cb0f04ed08b26acb6373f6b4c: removed 2 log segments from log reader
I20260812 06:17:18.091549 26296 log.cc:1079] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/f389340cb0f04ed08b26acb6373f6b4c/wal-000000001 (ops 1-6)
I20260812 06:17:18.091612 26296 log.cc:1079] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/f389340cb0f04ed08b26acb6373f6b4c/wal-000000002 (ops 7-11)
I20260812 06:17:18.096357 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: LogGCOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.005s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:18.096781 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling UndoDeltaBlockGCOp(f389340cb0f04ed08b26acb6373f6b4c): 16411392 bytes on disk
I20260812 06:17:18.097365 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: UndoDeltaBlockGCOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4}
I20260812 06:17:18.097790 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=2.188937
I20260812 06:17:18.109884 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.012s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3651384,"delete_count":0,"lbm_write_time_us":4183,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":445}
I20260812 06:17:18.110298 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=2.188937
I20260812 06:17:18.121464 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4394,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:18.122027 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling MajorDeltaCompactionOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=1.000000
I20260812 06:17:18.334008 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: MajorDeltaCompactionOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.212s	user 0.122s	sys 0.085s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774781,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1118,"lbm_read_time_us":14750,"lbm_reads_lt_1ms":569,"lbm_write_time_us":32019,"lbm_writes_lt_1ms":543,"mutex_wait_us":85,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":370,"threads_started":5,"update_count":2500}
I20260812 06:17:18.334690 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=14.095187
I20260812 06:17:18.376406 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.041s	user 0.026s	sys 0.012s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":17528,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:18.377121 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=2.188937
I20260812 06:17:18.402680 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.025s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6436,"lbm_writes_lt_1ms":103,"mutex_wait_us":2,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.403155 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=2.188937
I20260812 06:17:18.413342 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.010s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3995,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.413741 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling MajorDeltaCompactionOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=1.000000
I20260812 06:17:18.621831 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: MajorDeltaCompactionOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.208s	user 0.117s	sys 0.085s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877222,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":289,"lbm_read_time_us":13023,"lbm_reads_lt_1ms":673,"lbm_write_time_us":34465,"lbm_writes_lt_1ms":643,"mutex_wait_us":53,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13184,"update_count":3000}
I20260812 06:17:18.622532 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=14.095187
I20260812 06:17:18.673683 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.051s	user 0.025s	sys 0.025s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":22755,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:18.674229 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=2.188937
I20260812 06:17:18.686607 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4330,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.687177 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling MajorDeltaCompactionOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=1.000000
I20260812 06:17:18.871701 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: MajorDeltaCompactionOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.184s	user 0.125s	sys 0.052s 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":251,"lbm_read_time_us":11559,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28429,"lbm_writes_lt_1ms":543,"mutex_wait_us":38,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:17:18.872351 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=14.095187
I20260812 06:17:18.925230 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.053s	user 0.027s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20664,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:18.925698 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=2.188937
I20260812 06:17:18.936013 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.010s	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:17:18.936426 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling MajorDeltaCompactionOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=1.000000
I20260812 06:17:19.096630 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: MajorDeltaCompactionOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.160s	user 0.122s	sys 0.037s 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":902,"lbm_read_time_us":11209,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31789,"lbm_writes_lt_1ms":543,"mutex_wait_us":171,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2500}
I20260812 06:17:19.097337 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=10.126437
I20260812 06:17:19.136186 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.039s	user 0.024s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17226,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1500}
I20260812 06:17:19.136783 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=2.188937
I20260812 06:17:19.148589 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4224,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.149065 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling MajorDeltaCompactionOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=1.000000
I20260812 06:17:19.291301 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: MajorDeltaCompactionOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.142s	user 0.114s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":456,"lbm_read_time_us":8932,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27123,"lbm_writes_lt_1ms":443,"mutex_wait_us":71,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":20480,"update_count":2000}
I20260812 06:17:19.291987 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=10.126437
I20260812 06:17:19.334807 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.043s	user 0.020s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17323,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:19.335397 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=2.188937
I20260812 06:17:19.349915 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5636,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.350518 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushMRSOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=1.000000
I20260812 06:17:19.384341 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushMRSOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.034s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":252,"dirs.run_wall_time_us":1382,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2026,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:19.385073 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling LogGCOp(f389340cb0f04ed08b26acb6373f6b4c): free 112239315 bytes of WAL
I20260812 06:17:19.385322 26296 log_reader.cc:385] T f389340cb0f04ed08b26acb6373f6b4c: removed 11 log segments from log reader
I20260812 06:17:19.385392 26296 log.cc:1079] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/f389340cb0f04ed08b26acb6373f6b4c/wal-000000003 (ops 12-16)
I20260812 06:17:19.385442 26296 log.cc:1079] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/f389340cb0f04ed08b26acb6373f6b4c/wal-000000004 (ops 17-21)
I20260812 06:17:19.385497 26296 log.cc:1079] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/f389340cb0f04ed08b26acb6373f6b4c/wal-000000005 (ops 22-26)
I20260812 06:17:19.385541 26296 log.cc:1079] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/f389340cb0f04ed08b26acb6373f6b4c/wal-000000006 (ops 27-30)
I20260812 06:17:19.385581 26296 log.cc:1079] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/f389340cb0f04ed08b26acb6373f6b4c/wal-000000007 (ops 31-35)
I20260812 06:17:19.385623 26296 log.cc:1079] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/f389340cb0f04ed08b26acb6373f6b4c/wal-000000008 (ops 36-40)
I20260812 06:17:19.385663 26296 log.cc:1079] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/f389340cb0f04ed08b26acb6373f6b4c/wal-000000009 (ops 41-45)
I20260812 06:17:19.385701 26296 log.cc:1079] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/f389340cb0f04ed08b26acb6373f6b4c/wal-000000010 (ops 46-50)
I20260812 06:17:19.385740 26296 log.cc:1079] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/f389340cb0f04ed08b26acb6373f6b4c/wal-000000011 (ops 51-55)
I20260812 06:17:19.385778 26296 log.cc:1079] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/f389340cb0f04ed08b26acb6373f6b4c/wal-000000012 (ops 56-60)
I20260812 06:17:19.385818 26296 log.cc:1079] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/f389340cb0f04ed08b26acb6373f6b4c/wal-000000013 (ops 61-65)
I20260812 06:17:19.410643 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: LogGCOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.025s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:17:19.411082 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=2.188937
I20260812 06:17:19.425012 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.014s	user 0.008s	sys 0.003s Metrics: {"bytes_written":4143683,"delete_count":0,"lbm_write_time_us":4554,"lbm_writes_lt_1ms":104,"reinsert_count":0,"update_count":505}
I20260812 06:17:19.425536 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling LogGCOp(f389340cb0f04ed08b26acb6373f6b4c): free 12017983 bytes of WAL
I20260812 06:17:19.425765 26296 log_reader.cc:385] T f389340cb0f04ed08b26acb6373f6b4c: removed 1 log segments from log reader
I20260812 06:17:19.425835 26296 log.cc:1079] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/f389340cb0f04ed08b26acb6373f6b4c/wal-000000014 (ops 66-70)
I20260812 06:17:19.428149 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: LogGCOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:19.428516 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling UndoDeltaBlockGCOp(f389340cb0f04ed08b26acb6373f6b4c): 462 bytes on disk
I20260812 06:17:19.429026 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: UndoDeltaBlockGCOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:17:19.429510 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=2.188937
I20260812 06:17:19.441883 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.012s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4061634,"delete_count":0,"lbm_write_time_us":4611,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":495}
I20260812 06:17:19.442406 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling MajorDeltaCompactionOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=1.000000
I20260812 06:17:19.610188 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: MajorDeltaCompactionOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.168s	user 0.131s	sys 0.036s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877338,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":832,"lbm_read_time_us":12789,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32043,"lbm_writes_lt_1ms":643,"mutex_wait_us":341,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8704,"thread_start_us":83,"threads_started":1,"update_count":3000}
I20260812 06:17:19.610966 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=14.095187
I20260812 06:17:19.663587 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.052s	user 0.027s	sys 0.018s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21124,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:19.664161 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=2.188937
I20260812 06:17:19.689057 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.025s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5756,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.689620 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=2.188937
I20260812 06:17:19.699895 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3843,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.700519 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling MajorDeltaCompactionOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=1.000000
I20260812 06:17:19.883349 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: MajorDeltaCompactionOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.183s	user 0.152s	sys 0.030s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877218,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":803,"lbm_read_time_us":13932,"lbm_reads_lt_1ms":673,"lbm_write_time_us":37614,"lbm_writes_lt_1ms":643,"mutex_wait_us":282,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":3000}
I20260812 06:17:19.883980 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=14.095187
I20260812 06:17:19.928027 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.044s	user 0.032s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19016,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:19.928633 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=2.188937
I20260812 06:17:19.942957 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.014s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5100,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.943490 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling MajorDeltaCompactionOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=1.000000
I20260812 06:17:20.119779 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: MajorDeltaCompactionOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.176s	user 0.120s	sys 0.044s 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":248,"lbm_read_time_us":10306,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31912,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":2500}
I20260812 06:17:20.120590 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=14.095187
I20260812 06:17:20.176474 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.056s	user 0.044s	sys 0.008s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":25737,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:20.177119 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling MajorDeltaCompactionOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=1.000000
I20260812 06:17:20.336258 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: MajorDeltaCompactionOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.159s	user 0.103s	sys 0.053s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672159,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":417,"lbm_read_time_us":13176,"lbm_reads_lt_1ms":467,"lbm_write_time_us":24549,"lbm_writes_lt_1ms":443,"mutex_wait_us":87,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7168,"update_count":2000}
I20260812 06:17:20.336985 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=11.118625
I20260812 06:17:20.373402 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.036s	user 0.035s	sys 0.000s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15722,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:20.374046 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=2.188937
I20260812 06:17:20.389489 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5839,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:20.390024 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling MajorDeltaCompactionOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=1.000000
I20260812 06:17:20.524260 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: MajorDeltaCompactionOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.134s	user 0.111s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":845,"lbm_read_time_us":9589,"lbm_reads_lt_1ms":468,"lbm_write_time_us":25682,"lbm_writes_lt_1ms":443,"mutex_wait_us":281,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:20.524947 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=10.126437
I20260812 06:17:20.560770 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.036s	user 0.024s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13698,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:20.561305 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=2.188937
I20260812 06:17:20.576468 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5795,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.577140 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling MajorDeltaCompactionOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=1.000000
I20260812 06:17:20.703884 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: MajorDeltaCompactionOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.127s	user 0.094s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":972,"lbm_read_time_us":8506,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24477,"lbm_writes_lt_1ms":443,"mutex_wait_us":396,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5504,"update_count":2000}
I20260812 06:17:20.704469 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=10.126437
I20260812 06:17:20.749646 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.045s	user 0.019s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14071,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:20.750242 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=2.188937
I20260812 06:17:20.766080 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5859,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.766789 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushMRSOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=1.000000
I20260812 06:17:20.800189 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushMRSOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.033s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":255,"dirs.run_wall_time_us":1369,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2016,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:20.800925 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling LogGCOp(f389340cb0f04ed08b26acb6373f6b4c): free 116849467 bytes of WAL
I20260812 06:17:20.801153 26296 log_reader.cc:385] T f389340cb0f04ed08b26acb6373f6b4c: removed 12 log segments from log reader
I20260812 06:17:20.801200 26296 log.cc:1079] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/f389340cb0f04ed08b26acb6373f6b4c/wal-000000015 (ops 71-75)
I20260812 06:17:20.801231 26296 log.cc:1079] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/f389340cb0f04ed08b26acb6373f6b4c/wal-000000016 (ops 76-80)
I20260812 06:17:20.801297 26296 log.cc:1079] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/f389340cb0f04ed08b26acb6373f6b4c/wal-000000017 (ops 81-84)
I20260812 06:17:20.801339 26296 log.cc:1079] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/f389340cb0f04ed08b26acb6373f6b4c/wal-000000018 (ops 85-89)
I20260812 06:17:20.801384 26296 log.cc:1079] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/f389340cb0f04ed08b26acb6373f6b4c/wal-000000019 (ops 90-94)
I20260812 06:17:20.801435 26296 log.cc:1079] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/f389340cb0f04ed08b26acb6373f6b4c/wal-000000020 (ops 95-98)
I20260812 06:17:20.801472 26296 log.cc:1079] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/f389340cb0f04ed08b26acb6373f6b4c/wal-000000021 (ops 99-103)
I20260812 06:17:20.801512 26296 log.cc:1079] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/f389340cb0f04ed08b26acb6373f6b4c/wal-000000022 (ops 104-108)
I20260812 06:17:20.801548 26296 log.cc:1079] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/f389340cb0f04ed08b26acb6373f6b4c/wal-000000023 (ops 109-113)
I20260812 06:17:20.801589 26296 log.cc:1079] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/f389340cb0f04ed08b26acb6373f6b4c/wal-000000024 (ops 114-118)
I20260812 06:17:20.801627 26296 log.cc:1079] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/f389340cb0f04ed08b26acb6373f6b4c/wal-000000025 (ops 119-122)
I20260812 06:17:20.801666 26296 log.cc:1079] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/f389340cb0f04ed08b26acb6373f6b4c/wal-000000026 (ops 123-127)
I20260812 06:17:20.828697 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: LogGCOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.028s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:17:20.829088 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=3.181125
I20260812 06:17:20.841369 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4553932,"delete_count":0,"lbm_write_time_us":4941,"lbm_writes_lt_1ms":114,"reinsert_count":0,"update_count":555}
I20260812 06:17:20.841888 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=2.188937
I20260812 06:17:20.853145 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3651380,"delete_count":0,"lbm_write_time_us":3857,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":445}
I20260812 06:17:20.853765 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling MajorDeltaCompactionOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=1.000000
I20260812 06:17:21.032964 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: MajorDeltaCompactionOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.179s	user 0.132s	sys 0.047s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877334,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":567,"lbm_read_time_us":13470,"lbm_reads_lt_1ms":674,"lbm_write_time_us":37011,"lbm_writes_lt_1ms":643,"mutex_wait_us":39,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4992,"thread_start_us":89,"threads_started":1,"update_count":3000}
I20260812 06:17:21.033823 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling UndoDeltaBlockGCOp(f389340cb0f04ed08b26acb6373f6b4c): 462 bytes on disk
I20260812 06:17:21.034456 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: UndoDeltaBlockGCOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":100,"lbm_reads_lt_1ms":4}
I20260812 06:17:21.035501 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=14.095187
I20260812 06:17:21.089735 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.054s	user 0.050s	sys 0.003s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23816,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:21.090520 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=2.188937
I20260812 06:17:21.108166 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.017s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6929,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.108739 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling MajorDeltaCompactionOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=1.000000
I20260812 06:17:21.284353 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: MajorDeltaCompactionOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.175s	user 0.124s	sys 0.049s 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":750,"lbm_read_time_us":11178,"lbm_reads_lt_1ms":564,"lbm_write_time_us":33980,"lbm_writes_lt_1ms":543,"mutex_wait_us":341,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":29568,"update_count":2500}
I20260812 06:17:21.285073 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=14.095187
I20260812 06:17:21.350725 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.065s	user 0.037s	sys 0.012s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":22898,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:21.351244 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=2.188937
I20260812 06:17:21.362792 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4429,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.363605 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling MajorDeltaCompactionOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=1.000000
I20260812 06:17:21.555145 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: MajorDeltaCompactionOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.191s	user 0.145s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":330,"lbm_read_time_us":11855,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30620,"lbm_writes_lt_1ms":543,"mutex_wait_us":63,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:17:21.555773 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=14.095187
I20260812 06:17:21.617726 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.062s	user 0.046s	sys 0.003s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22652,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:21.618259 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=2.188937
I20260812 06:17:21.628983 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4295,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.629671 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling MajorDeltaCompactionOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=1.000000
I20260812 06:17:21.818934 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: MajorDeltaCompactionOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.189s	user 0.124s	sys 0.064s 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":174,"lbm_read_time_us":14102,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33229,"lbm_writes_lt_1ms":543,"mutex_wait_us":44,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2500}
I20260812 06:17:21.819774 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=14.095187
I20260812 06:17:21.890235 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.070s	user 0.047s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25437,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:21.890913 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=2.188937
I20260812 06:17:21.903110 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4803,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.903640 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling MajorDeltaCompactionOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=1.000000
I20260812 06:17:22.097077 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: MajorDeltaCompactionOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.193s	user 0.129s	sys 0.064s 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":318,"lbm_read_time_us":14484,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31791,"lbm_writes_lt_1ms":543,"mutex_wait_us":74,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2500}
I20260812 06:17:22.100414 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=14.095187
I20260812 06:17:22.165459 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.065s	user 0.036s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24553,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:22.166157 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=2.188937
I20260812 06:17:22.177722 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4389,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:22.178234 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling MajorDeltaCompactionOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=1.000000
I20260812 06:17:22.378043 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: MajorDeltaCompactionOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.200s	user 0.115s	sys 0.071s 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":668,"lbm_read_time_us":13510,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32269,"lbm_writes_lt_1ms":543,"mutex_wait_us":288,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":33536,"update_count":2500}
I20260812 06:17:22.378825 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=14.095187
I20260812 06:17:22.434442 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.055s	user 0.026s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23352,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:22.435065 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=2.188937
I20260812 06:17:22.446048 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4453,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:22.447002 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushMRSOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=1.000000
I20260812 06:17:22.484979 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushMRSOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.038s	user 0.029s	sys 0.003s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":91,"dirs.run_cpu_time_us":201,"dirs.run_wall_time_us":1472,"drs_written":1,"lbm_read_time_us":101,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1756,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:22.485752 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling LogGCOp(f389340cb0f04ed08b26acb6373f6b4c): free 133024644 bytes of WAL
I20260812 06:17:22.486042 26296 log_reader.cc:385] T f389340cb0f04ed08b26acb6373f6b4c: removed 13 log segments from log reader
I20260812 06:17:22.486105 26296 log.cc:1079] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/f389340cb0f04ed08b26acb6373f6b4c/wal-000000027 (ops 128-132)
I20260812 06:17:22.486147 26296 log.cc:1079] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/f389340cb0f04ed08b26acb6373f6b4c/wal-000000028 (ops 133-137)
I20260812 06:17:22.486181 26296 log.cc:1079] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/f389340cb0f04ed08b26acb6373f6b4c/wal-000000029 (ops 138-142)
I20260812 06:17:22.486209 26296 log.cc:1079] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/f389340cb0f04ed08b26acb6373f6b4c/wal-000000030 (ops 143-146)
I20260812 06:17:22.486230 26296 log.cc:1079] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/f389340cb0f04ed08b26acb6373f6b4c/wal-000000031 (ops 147-151)
I20260812 06:17:22.486261 26296 log.cc:1079] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/f389340cb0f04ed08b26acb6373f6b4c/wal-000000032 (ops 152-156)
I20260812 06:17:22.486291 26296 log.cc:1079] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/f389340cb0f04ed08b26acb6373f6b4c/wal-000000033 (ops 157-161)
I20260812 06:17:22.486318 26296 log.cc:1079] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/f389340cb0f04ed08b26acb6373f6b4c/wal-000000034 (ops 162-166)
I20260812 06:17:22.486343 26296 log.cc:1079] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/f389340cb0f04ed08b26acb6373f6b4c/wal-000000035 (ops 167-171)
I20260812 06:17:22.486366 26296 log.cc:1079] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/f389340cb0f04ed08b26acb6373f6b4c/wal-000000036 (ops 172-176)
I20260812 06:17:22.486395 26296 log.cc:1079] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/f389340cb0f04ed08b26acb6373f6b4c/wal-000000037 (ops 177-181)
I20260812 06:17:22.486420 26296 log.cc:1079] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/f389340cb0f04ed08b26acb6373f6b4c/wal-000000038 (ops 182-186)
I20260812 06:17:22.486449 26296 log.cc:1079] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: Deleting log segment in path: /tmp/dist-test-tasksAU7D3/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515431708129-25840-0/minicluster-data/ts-0-root/wals/f389340cb0f04ed08b26acb6373f6b4c/wal-000000039 (ops 187-191)
I20260812 06:17:22.517988 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: LogGCOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.032s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:17:22.518643 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling UndoDeltaBlockGCOp(f389340cb0f04ed08b26acb6373f6b4c): 493 bytes on disk
I20260812 06:17:22.519266 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: UndoDeltaBlockGCOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":83,"lbm_reads_lt_1ms":4}
I20260812 06:17:22.519886 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=3.181125
I20260812 06:17:22.546133 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.026s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5219,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:22.546593 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=2.188937
I20260812 06:17:22.556420 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3705,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:22.557070 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling MajorDeltaCompactionOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=1.000000
I20260812 06:17:22.755131 25840 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.997s	user 1.809s	sys 0.168s
I20260812 06:17:22.778080 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: MajorDeltaCompactionOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.221s	user 0.168s	sys 0.051s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979741,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":15458,"lbm_reads_lt_1ms":770,"lbm_write_time_us":38608,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":3500}
I20260812 06:17:22.778719 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=14.095187
I20260812 06:17:22.812325 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: FlushDeltaMemStoresOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.033s	user 0.024s	sys 0.008s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":16733,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:22.812888 26392 maintenance_manager.cc:419] P 3f1c56bee3f3443197fe1f19dd2bb1e0: Scheduling MajorDeltaCompactionOp(f389340cb0f04ed08b26acb6373f6b4c): perf score=1.000000
I20260812 06:17:22.869103 25840 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.114s	user 0.002s	sys 0.000s
I20260812 06:17:22.869643 25840 tablet_server.cc:179] TabletServer@127.25.60.1:0 shutting down...
I20260812 06:17:22.951025 26296 maintenance_manager.cc:643] P 3f1c56bee3f3443197fe1f19dd2bb1e0: MajorDeltaCompactionOp(f389340cb0f04ed08b26acb6373f6b4c) complete. Timing: real 0.138s	user 0.088s	sys 0.049s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672156,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":656,"lbm_read_time_us":10228,"lbm_reads_lt_1ms":467,"lbm_write_time_us":31428,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":441,"mutex_wait_us":261,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18304,"update_count":2000}
I20260812 06:17:22.951784 25840 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:22.952099 25840 tablet_replica.cc:333] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0: stopping tablet replica
I20260812 06:17:22.952242 25840 raft_consensus.cc:2243] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:22.952428 25840 raft_consensus.cc:2272] T f389340cb0f04ed08b26acb6373f6b4c P 3f1c56bee3f3443197fe1f19dd2bb1e0 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:22.956558 25840 tablet_server.cc:196] TabletServer@127.25.60.1:0 shutdown complete.
I20260812 06:17:22.991731 25840 master.cc:562] Master@127.25.60.62:45037 shutting down...
I20260812 06:17:22.994792 25840 raft_consensus.cc:2243] T 00000000000000000000000000000000 P dc26d86fd045405c996030df9a006305 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:22.994951 25840 raft_consensus.cc:2272] T 00000000000000000000000000000000 P dc26d86fd045405c996030df9a006305 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:22.995007 25840 tablet_replica.cc:333] T 00000000000000000000000000000000 P dc26d86fd045405c996030df9a006305: stopping tablet replica
I20260812 06:17:23.007469 25840 master.cc:584] Master@127.25.60.62:45037 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5593 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11380 ms total)

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