[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:19:41.845368 19454 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.18.255.190:33447
I20260812 06:19:41.846475 19454 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:19:41.847150 19454 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:41.854243 19464 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:41.854246 19459 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:41.854303 19454 server_base.cc:1061] running on GCE node
W20260812 06:19:41.854508 19462 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:41.855317 19454 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:41.855425 19454 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:41.855454 19454 hybrid_clock.cc:648] HybridClock initialized: now 1786515581855452 us; error 0 us; skew 500 ppm
I20260812 06:19:41.857563 19454 webserver.cc:533] Webserver started at http://127.18.255.190:34955/ using document root <none> and password file <none>
I20260812 06:19:41.858214 19454 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:41.858283 19454 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:41.858561 19454 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:41.860402 19454 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/master-0-root/instance:
uuid: "e6c420f7bec64fe98f4d54c1e665902e"
format_stamp: "Formatted at 2026-08-12 06:19:41 on dist-test-slave-dhph"
I20260812 06:19:41.864537 19454 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.003s	sys 0.001s
I20260812 06:19:41.867319 19469 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:41.868633 19454 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:41.868875 19454 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/master-0-root
uuid: "e6c420f7bec64fe98f4d54c1e665902e"
format_stamp: "Formatted at 2026-08-12 06:19:41 on dist-test-slave-dhph"
I20260812 06:19:41.869015 19454 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:41.887516 19454 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:41.888245 19454 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:19:41.888450 19454 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:41.897423 19454 rpc_server.cc:307] RPC server started. Bound to: 127.18.255.190:33447
I20260812 06:19:41.897480 19529 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.18.255.190:33447 every 8 connection(s)
I20260812 06:19:41.900661 19530 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:41.907435 19530 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e6c420f7bec64fe98f4d54c1e665902e: Bootstrap starting.
I20260812 06:19:41.910392 19530 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P e6c420f7bec64fe98f4d54c1e665902e: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:41.911597 19530 log.cc:826] T 00000000000000000000000000000000 P e6c420f7bec64fe98f4d54c1e665902e: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:41.913851 19530 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e6c420f7bec64fe98f4d54c1e665902e: No bootstrap required, opened a new log
I20260812 06:19:41.917333 19530 raft_consensus.cc:359] T 00000000000000000000000000000000 P e6c420f7bec64fe98f4d54c1e665902e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e6c420f7bec64fe98f4d54c1e665902e" member_type: VOTER }
I20260812 06:19:41.917587 19530 raft_consensus.cc:385] T 00000000000000000000000000000000 P e6c420f7bec64fe98f4d54c1e665902e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:41.917711 19530 raft_consensus.cc:740] T 00000000000000000000000000000000 P e6c420f7bec64fe98f4d54c1e665902e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e6c420f7bec64fe98f4d54c1e665902e, State: Initialized, Role: FOLLOWER
I20260812 06:19:41.918407 19530 consensus_queue.cc:260] T 00000000000000000000000000000000 P e6c420f7bec64fe98f4d54c1e665902e [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: "e6c420f7bec64fe98f4d54c1e665902e" member_type: VOTER }
I20260812 06:19:41.918649 19530 raft_consensus.cc:399] T 00000000000000000000000000000000 P e6c420f7bec64fe98f4d54c1e665902e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:41.918756 19530 raft_consensus.cc:493] T 00000000000000000000000000000000 P e6c420f7bec64fe98f4d54c1e665902e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:41.918934 19530 raft_consensus.cc:3060] T 00000000000000000000000000000000 P e6c420f7bec64fe98f4d54c1e665902e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:41.919946 19530 raft_consensus.cc:515] T 00000000000000000000000000000000 P e6c420f7bec64fe98f4d54c1e665902e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e6c420f7bec64fe98f4d54c1e665902e" member_type: VOTER }
I20260812 06:19:41.920488 19530 leader_election.cc:304] T 00000000000000000000000000000000 P e6c420f7bec64fe98f4d54c1e665902e [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: e6c420f7bec64fe98f4d54c1e665902e; no voters: 
I20260812 06:19:41.920921 19530 leader_election.cc:290] T 00000000000000000000000000000000 P e6c420f7bec64fe98f4d54c1e665902e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:41.921139 19533 raft_consensus.cc:2804] T 00000000000000000000000000000000 P e6c420f7bec64fe98f4d54c1e665902e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:41.921415 19533 raft_consensus.cc:697] T 00000000000000000000000000000000 P e6c420f7bec64fe98f4d54c1e665902e [term 1 LEADER]: Becoming Leader. State: Replica: e6c420f7bec64fe98f4d54c1e665902e, State: Running, Role: LEADER
I20260812 06:19:41.921906 19533 consensus_queue.cc:237] T 00000000000000000000000000000000 P e6c420f7bec64fe98f4d54c1e665902e [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: "e6c420f7bec64fe98f4d54c1e665902e" member_type: VOTER }
I20260812 06:19:41.922160 19530 sys_catalog.cc:565] T 00000000000000000000000000000000 P e6c420f7bec64fe98f4d54c1e665902e [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:41.924194 19534 sys_catalog.cc:455] T 00000000000000000000000000000000 P e6c420f7bec64fe98f4d54c1e665902e [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "e6c420f7bec64fe98f4d54c1e665902e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e6c420f7bec64fe98f4d54c1e665902e" member_type: VOTER } }
I20260812 06:19:41.924252 19536 sys_catalog.cc:455] T 00000000000000000000000000000000 P e6c420f7bec64fe98f4d54c1e665902e [sys.catalog]: SysCatalogTable state changed. Reason: New leader e6c420f7bec64fe98f4d54c1e665902e. Latest consensus state: current_term: 1 leader_uuid: "e6c420f7bec64fe98f4d54c1e665902e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e6c420f7bec64fe98f4d54c1e665902e" member_type: VOTER } }
I20260812 06:19:41.924389 19534 sys_catalog.cc:458] T 00000000000000000000000000000000 P e6c420f7bec64fe98f4d54c1e665902e [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:41.924389 19536 sys_catalog.cc:458] T 00000000000000000000000000000000 P e6c420f7bec64fe98f4d54c1e665902e [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:41.924762 19547 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:41.924940 19454 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:41.927314 19547 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:41.932396 19547 catalog_manager.cc:1383] Generated new cluster ID: 796edd8f254046c3948ac5197a709a95
I20260812 06:19:41.932492 19547 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:41.946064 19547 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:41.947171 19547 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:41.957918 19547 catalog_manager.cc:6092] T 00000000000000000000000000000000 P e6c420f7bec64fe98f4d54c1e665902e: Generated new TSK 0
I20260812 06:19:41.959064 19547 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:41.990113 19454 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:41.993244 19558 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:41.993402 19555 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:41.993517 19556 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:41.993953 19454 server_base.cc:1061] running on GCE node
I20260812 06:19:41.994153 19454 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:41.994275 19454 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:41.994313 19454 hybrid_clock.cc:648] HybridClock initialized: now 1786515581994311 us; error 0 us; skew 500 ppm
I20260812 06:19:41.995472 19454 webserver.cc:533] Webserver started at http://127.18.255.129:40333/ using document root <none> and password file <none>
I20260812 06:19:41.995667 19454 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:41.995744 19454 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:41.995859 19454 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:41.996287 19454 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/instance:
uuid: "5283fd1a4367438880f8bcb67a20b16f"
format_stamp: "Formatted at 2026-08-12 06:19:41 on dist-test-slave-dhph"
I20260812 06:19:41.997969 19454 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:41.999217 19565 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:41.999505 19454 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:41.999585 19454 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root
uuid: "5283fd1a4367438880f8bcb67a20b16f"
format_stamp: "Formatted at 2026-08-12 06:19:41 on dist-test-slave-dhph"
I20260812 06:19:41.999682 19454 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:42.025947 19454 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:42.026943 19454 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:42.027510 19454 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:42.028451 19454 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:42.028503 19454 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:42.028574 19454 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:42.028618 19454 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:42.035804 19454 rpc_server.cc:307] RPC server started. Bound to: 127.18.255.129:42757
I20260812 06:19:42.035858 19637 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.18.255.129:42757 every 8 connection(s)
I20260812 06:19:42.046145 19638 heartbeater.cc:344] Connected to a master server at 127.18.255.190:33447
I20260812 06:19:42.046447 19638 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:42.046977 19638 heartbeater.cc:507] Master 127.18.255.190:33447 requested a full tablet report, sending...
I20260812 06:19:42.048564 19486 ts_manager.cc:194] Registered new tserver with Master: 5283fd1a4367438880f8bcb67a20b16f (127.18.255.129:42757)
I20260812 06:19:42.048847 19454 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01235345s
I20260812 06:19:42.050001 19486 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:54514
I20260812 06:19:42.060242 19486 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:54520:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:42.075155 19596 tablet_service.cc:1511] Processing CreateTablet for tablet 811e4c330f774f76861443f23f90c2c6 (DEFAULT_TABLE table=heavy-update-compaction-test [id=77e7a4b21bf84cfbad80f948483b52f2]), partition=
I20260812 06:19:42.075738 19596 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 811e4c330f774f76861443f23f90c2c6. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:42.078615 19654 tablet_bootstrap.cc:492] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Bootstrap starting.
I20260812 06:19:42.080219 19654 tablet_bootstrap.cc:654] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:42.081452 19654 tablet_bootstrap.cc:492] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: No bootstrap required, opened a new log
I20260812 06:19:42.081589 19654 ts_tablet_manager.cc:1403] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:42.082078 19654 raft_consensus.cc:359] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5283fd1a4367438880f8bcb67a20b16f" member_type: VOTER last_known_addr { host: "127.18.255.129" port: 42757 } }
I20260812 06:19:42.082211 19654 raft_consensus.cc:385] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:42.082257 19654 raft_consensus.cc:740] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5283fd1a4367438880f8bcb67a20b16f, State: Initialized, Role: FOLLOWER
I20260812 06:19:42.082446 19654 consensus_queue.cc:260] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f [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: "5283fd1a4367438880f8bcb67a20b16f" member_type: VOTER last_known_addr { host: "127.18.255.129" port: 42757 } }
I20260812 06:19:42.082558 19654 raft_consensus.cc:399] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:42.082633 19654 raft_consensus.cc:493] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:42.082690 19654 raft_consensus.cc:3060] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:42.083575 19654 raft_consensus.cc:515] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5283fd1a4367438880f8bcb67a20b16f" member_type: VOTER last_known_addr { host: "127.18.255.129" port: 42757 } }
I20260812 06:19:42.083771 19654 leader_election.cc:304] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f [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: 5283fd1a4367438880f8bcb67a20b16f; no voters: 
I20260812 06:19:42.084023 19654 leader_election.cc:290] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:42.084152 19657 raft_consensus.cc:2804] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:42.084460 19657 raft_consensus.cc:697] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f [term 1 LEADER]: Becoming Leader. State: Replica: 5283fd1a4367438880f8bcb67a20b16f, State: Running, Role: LEADER
I20260812 06:19:42.084465 19654 ts_tablet_manager.cc:1434] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:42.084694 19638 heartbeater.cc:499] Master 127.18.255.190:33447 was elected leader, sending a full tablet report...
I20260812 06:19:42.084905 19657 consensus_queue.cc:237] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f [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: "5283fd1a4367438880f8bcb67a20b16f" member_type: VOTER last_known_addr { host: "127.18.255.129" port: 42757 } }
I20260812 06:19:42.088042 19486 catalog_manager.cc:5719] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f reported cstate change: term changed from 0 to 1, leader changed from <none> to 5283fd1a4367438880f8bcb67a20b16f (127.18.255.129). New cstate: current_term: 1 leader_uuid: "5283fd1a4367438880f8bcb67a20b16f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5283fd1a4367438880f8bcb67a20b16f" member_type: VOTER last_known_addr { host: "127.18.255.129" port: 42757 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:42.157096 19454 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.059s	user 0.018s	sys 0.008s
I20260812 06:19:42.287153 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushMRSOp(811e4c330f774f76861443f23f90c2c6): perf score=15.086190
I20260812 06:19:42.465175 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushMRSOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.178s	user 0.115s	sys 0.052s Metrics: {"bytes_written":11897252,"cfile_init":1,"compiler_manager_pool.queue_time_us":220,"delete_count":0,"dirs.queue_time_us":48,"dirs.run_cpu_time_us":205,"dirs.run_wall_time_us":1095,"drs_written":1,"lbm_read_time_us":83,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43589,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":1280,"thread_start_us":116,"threads_started":1,"update_count":1450}
I20260812 06:19:42.466562 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling LogGCOp(811e4c330f774f76861443f23f90c2c6): free 20743880 bytes of WAL
I20260812 06:19:42.466974 19571 log_reader.cc:385] T 811e4c330f774f76861443f23f90c2c6: removed 2 log segments from log reader
I20260812 06:19:42.467046 19571 log.cc:1079] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/811e4c330f774f76861443f23f90c2c6/wal-000000001 (ops 1-6)
I20260812 06:19:42.467152 19571 log.cc:1079] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/811e4c330f774f76861443f23f90c2c6/wal-000000002 (ops 7-11)
I20260812 06:19:42.472740 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: LogGCOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.006s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:19:42.473265 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling UndoDeltaBlockGCOp(811e4c330f774f76861443f23f90c2c6): 12719217 bytes on disk
I20260812 06:19:42.473974 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: UndoDeltaBlockGCOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4}
I20260812 06:19:42.474409 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=2.188937
I20260812 06:19:42.496634 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.022s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6822,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.497125 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling MajorDeltaCompactionOp(811e4c330f774f76861443f23f90c2c6): perf score=1.000000
I20260812 06:19:42.630318 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: MajorDeltaCompactionOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.133s	user 0.124s	sys 0.009s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262039,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":953,"lbm_read_time_us":8157,"lbm_reads_lt_1ms":450,"lbm_write_time_us":24055,"lbm_writes_lt_1ms":433,"mutex_wait_us":21,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":16896,"thread_start_us":330,"threads_started":5,"update_count":1950}
I20260812 06:19:42.631233 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=10.126437
I20260812 06:19:42.677472 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.046s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16458,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:42.677996 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=2.188937
I20260812 06:19:42.688841 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4086,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.689607 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling MajorDeltaCompactionOp(811e4c330f774f76861443f23f90c2c6): perf score=1.000000
I20260812 06:19:42.814497 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: MajorDeltaCompactionOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.125s	user 0.108s	sys 0.016s 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":219,"lbm_read_time_us":9410,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22923,"lbm_writes_lt_1ms":443,"mutex_wait_us":64,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5760,"update_count":2000}
I20260812 06:19:42.815202 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=10.126437
I20260812 06:19:42.857892 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.043s	user 0.022s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15958,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:42.858460 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=2.188937
I20260812 06:19:42.869917 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4297,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.870401 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling MajorDeltaCompactionOp(811e4c330f774f76861443f23f90c2c6): perf score=1.000000
I20260812 06:19:43.003602 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: MajorDeltaCompactionOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.133s	user 0.092s	sys 0.035s 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":798,"lbm_read_time_us":9729,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25449,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2000}
I20260812 06:19:43.004487 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=10.126437
I20260812 06:19:43.063963 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.059s	user 0.018s	sys 0.027s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17885,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:43.064527 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=2.188937
I20260812 06:19:43.075632 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4377,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.076109 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling MajorDeltaCompactionOp(811e4c330f774f76861443f23f90c2c6): perf score=1.000000
I20260812 06:19:43.234807 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: MajorDeltaCompactionOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.159s	user 0.119s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":269,"lbm_read_time_us":12039,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24919,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:43.235551 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=10.126437
I20260812 06:19:43.280289 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.045s	user 0.026s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15552,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:43.280810 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=2.188937
I20260812 06:19:43.291919 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4165,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.292634 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling MajorDeltaCompactionOp(811e4c330f774f76861443f23f90c2c6): perf score=1.000000
I20260812 06:19:43.413489 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: MajorDeltaCompactionOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.121s	user 0.092s	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":1814,"lbm_read_time_us":8123,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24284,"lbm_writes_lt_1ms":443,"mutex_wait_us":507,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:19:43.414213 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=10.126437
I20260812 06:19:43.454769 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.040s	user 0.029s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15632,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:43.455284 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=2.188937
I20260812 06:19:43.466722 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.011s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4200,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.467347 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling MajorDeltaCompactionOp(811e4c330f774f76861443f23f90c2c6): perf score=1.000000
I20260812 06:19:43.599290 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: MajorDeltaCompactionOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.132s	user 0.097s	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":249,"lbm_read_time_us":9542,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26240,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":2000}
I20260812 06:19:43.599838 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=10.126437
I20260812 06:19:43.647680 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.048s	user 0.015s	sys 0.026s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14916,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:43.648255 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=1.000000
I20260812 06:19:43.658246 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.010s	user 0.004s	sys 0.000s Metrics: {"bytes_written":1477056,"delete_count":0,"lbm_write_time_us":1879,"lbm_writes_lt_1ms":39,"reinsert_count":0,"update_count":180}
I20260812 06:19:43.658872 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=1.196750
I20260812 06:19:43.666908 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.008s	user 0.007s	sys 0.001s Metrics: {"bytes_written":2625754,"delete_count":0,"lbm_write_time_us":2785,"lbm_writes_lt_1ms":67,"reinsert_count":0,"update_count":320}
I20260812 06:19:43.667444 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling MajorDeltaCompactionOp(811e4c330f774f76861443f23f90c2c6): perf score=1.000000
I20260812 06:19:43.833822 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: MajorDeltaCompactionOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.166s	user 0.080s	sys 0.077s Metrics: {"cfile_cache_miss":433,"cfile_cache_miss_bytes":20672302,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":204,"lbm_read_time_us":10473,"lbm_reads_lt_1ms":473,"lbm_write_time_us":26611,"lbm_writes_lt_1ms":443,"mutex_wait_us":41,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":74240,"update_count":2000}
I20260812 06:19:43.834685 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=10.126437
I20260812 06:19:43.883562 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.049s	user 0.019s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16101,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:43.884097 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=2.188937
I20260812 06:19:43.895754 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4494,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.896458 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushMRSOp(811e4c330f774f76861443f23f90c2c6): perf score=1.000000
I20260812 06:19:43.931169 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushMRSOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.035s	user 0.030s	sys 0.004s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":270,"dirs.run_wall_time_us":1647,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2022,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:43.932149 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling LogGCOp(811e4c330f774f76861443f23f90c2c6): free 121006444 bytes of WAL
I20260812 06:19:43.932528 19571 log_reader.cc:385] T 811e4c330f774f76861443f23f90c2c6: removed 12 log segments from log reader
I20260812 06:19:43.932608 19571 log.cc:1079] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/811e4c330f774f76861443f23f90c2c6/wal-000000003 (ops 12-16)
I20260812 06:19:43.932652 19571 log.cc:1079] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/811e4c330f774f76861443f23f90c2c6/wal-000000004 (ops 17-21)
I20260812 06:19:43.932675 19571 log.cc:1079] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/811e4c330f774f76861443f23f90c2c6/wal-000000005 (ops 22-26)
I20260812 06:19:43.932698 19571 log.cc:1079] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/811e4c330f774f76861443f23f90c2c6/wal-000000006 (ops 27-31)
I20260812 06:19:43.932729 19571 log.cc:1079] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/811e4c330f774f76861443f23f90c2c6/wal-000000007 (ops 32-36)
I20260812 06:19:43.932752 19571 log.cc:1079] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/811e4c330f774f76861443f23f90c2c6/wal-000000008 (ops 37-41)
I20260812 06:19:43.932773 19571 log.cc:1079] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/811e4c330f774f76861443f23f90c2c6/wal-000000009 (ops 42-46)
I20260812 06:19:43.932796 19571 log.cc:1079] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/811e4c330f774f76861443f23f90c2c6/wal-000000010 (ops 47-51)
I20260812 06:19:43.932818 19571 log.cc:1079] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/811e4c330f774f76861443f23f90c2c6/wal-000000011 (ops 52-56)
I20260812 06:19:43.932842 19571 log.cc:1079] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/811e4c330f774f76861443f23f90c2c6/wal-000000012 (ops 57-60)
I20260812 06:19:43.932868 19571 log.cc:1079] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/811e4c330f774f76861443f23f90c2c6/wal-000000013 (ops 61-65)
I20260812 06:19:43.932902 19571 log.cc:1079] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/811e4c330f774f76861443f23f90c2c6/wal-000000014 (ops 66-70)
I20260812 06:19:43.962508 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: LogGCOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.030s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:43.963001 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling UndoDeltaBlockGCOp(811e4c330f774f76861443f23f90c2c6): 483 bytes on disk
I20260812 06:19:43.963668 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: UndoDeltaBlockGCOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":108,"lbm_reads_lt_1ms":4}
I20260812 06:19:43.964336 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=2.188937
I20260812 06:19:43.994875 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.030s	user 0.017s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6752,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":500}
I20260812 06:19:43.995450 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling LogGCOp(811e4c330f774f76861443f23f90c2c6): free 11564875 bytes of WAL
I20260812 06:19:43.995688 19571 log_reader.cc:385] T 811e4c330f774f76861443f23f90c2c6: removed 1 log segments from log reader
I20260812 06:19:43.995734 19571 log.cc:1079] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/811e4c330f774f76861443f23f90c2c6/wal-000000015 (ops 71-74)
I20260812 06:19:43.998160 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: LogGCOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:43.998632 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=2.188937
I20260812 06:19:44.010353 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.012s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4627,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.010921 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling MajorDeltaCompactionOp(811e4c330f774f76861443f23f90c2c6): perf score=1.000000
I20260812 06:19:44.234349 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: MajorDeltaCompactionOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.223s	user 0.149s	sys 0.064s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877337,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1201,"lbm_read_time_us":15245,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36831,"lbm_writes_lt_1ms":643,"mutex_wait_us":27,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9600,"thread_start_us":107,"threads_started":1,"update_count":3000}
I20260812 06:19:44.235056 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=14.095187
I20260812 06:19:44.299338 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.064s	user 0.025s	sys 0.039s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26143,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:44.300175 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=2.188937
I20260812 06:19:44.318938 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.019s	user 0.010s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7291,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.319445 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling MajorDeltaCompactionOp(811e4c330f774f76861443f23f90c2c6): perf score=1.000000
I20260812 06:19:44.510826 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: MajorDeltaCompactionOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.191s	user 0.136s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1210,"lbm_read_time_us":12990,"lbm_reads_lt_1ms":568,"lbm_write_time_us":30179,"lbm_writes_lt_1ms":543,"mutex_wait_us":319,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":2500}
I20260812 06:19:44.511623 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=14.095187
I20260812 06:19:44.564349 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.052s	user 0.026s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23116,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:44.564998 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=2.188937
I20260812 06:19:44.585266 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.020s	user 0.017s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6766,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.586052 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling MajorDeltaCompactionOp(811e4c330f774f76861443f23f90c2c6): perf score=1.000000
I20260812 06:19:44.784929 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: MajorDeltaCompactionOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.199s	user 0.142s	sys 0.044s 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":230,"lbm_read_time_us":15361,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29450,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17152,"update_count":2500}
I20260812 06:19:44.785465 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=14.095187
I20260812 06:19:44.847095 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.061s	user 0.024s	sys 0.028s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23727,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:44.847579 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=2.188937
I20260812 06:19:44.858556 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4316,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.859200 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling MajorDeltaCompactionOp(811e4c330f774f76861443f23f90c2c6): perf score=1.000000
I20260812 06:19:45.048516 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: MajorDeltaCompactionOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.189s	user 0.132s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":901,"lbm_read_time_us":12361,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33196,"lbm_writes_lt_1ms":543,"mutex_wait_us":272,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2500}
I20260812 06:19:45.049286 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=11.118625
I20260812 06:19:45.090320 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.041s	user 0.014s	sys 0.024s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18119,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:45.091097 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=2.188937
I20260812 06:19:45.106469 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.015s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5372,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:45.107102 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling MajorDeltaCompactionOp(811e4c330f774f76861443f23f90c2c6): perf score=1.000000
I20260812 06:19:45.237534 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: MajorDeltaCompactionOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.130s	user 0.103s	sys 0.024s 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":669,"lbm_read_time_us":9107,"lbm_reads_lt_1ms":468,"lbm_write_time_us":25510,"lbm_writes_lt_1ms":443,"mutex_wait_us":19,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13824,"update_count":2000}
I20260812 06:19:45.238260 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=10.126437
I20260812 06:19:45.284569 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.046s	user 0.024s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21187,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:45.285182 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=2.188937
I20260812 06:19:45.300067 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5737,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.300714 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling MajorDeltaCompactionOp(811e4c330f774f76861443f23f90c2c6): perf score=1.000000
I20260812 06:19:45.430533 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: MajorDeltaCompactionOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.130s	user 0.103s	sys 0.024s 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":840,"lbm_read_time_us":8653,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24148,"lbm_writes_lt_1ms":443,"mutex_wait_us":264,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:19:45.431145 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=10.126437
I20260812 06:19:45.480782 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.049s	user 0.014s	sys 0.033s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17092,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:45.481493 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=2.188937
I20260812 06:19:45.492503 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4248,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.493162 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushMRSOp(811e4c330f774f76861443f23f90c2c6): perf score=1.000000
I20260812 06:19:45.537200 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushMRSOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.044s	user 0.034s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":226,"dirs.run_wall_time_us":1698,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1747,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29,"spinlock_wait_cycles":52480}
I20260812 06:19:45.538060 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling LogGCOp(811e4c330f774f76861443f23f90c2c6): free 112239316 bytes of WAL
I20260812 06:19:45.538306 19571 log_reader.cc:385] T 811e4c330f774f76861443f23f90c2c6: removed 11 log segments from log reader
I20260812 06:19:45.538355 19571 log.cc:1079] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/811e4c330f774f76861443f23f90c2c6/wal-000000016 (ops 75-79)
I20260812 06:19:45.538388 19571 log.cc:1079] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/811e4c330f774f76861443f23f90c2c6/wal-000000017 (ops 80-84)
I20260812 06:19:45.538458 19571 log.cc:1079] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/811e4c330f774f76861443f23f90c2c6/wal-000000018 (ops 85-89)
I20260812 06:19:45.538503 19571 log.cc:1079] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/811e4c330f774f76861443f23f90c2c6/wal-000000019 (ops 90-94)
I20260812 06:19:45.538555 19571 log.cc:1079] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/811e4c330f774f76861443f23f90c2c6/wal-000000020 (ops 95-99)
I20260812 06:19:45.538720 19571 log.cc:1079] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/811e4c330f774f76861443f23f90c2c6/wal-000000021 (ops 100-104)
I20260812 06:19:45.538770 19571 log.cc:1079] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/811e4c330f774f76861443f23f90c2c6/wal-000000022 (ops 105-109)
I20260812 06:19:45.538816 19571 log.cc:1079] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/811e4c330f774f76861443f23f90c2c6/wal-000000023 (ops 110-114)
I20260812 06:19:45.538859 19571 log.cc:1079] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/811e4c330f774f76861443f23f90c2c6/wal-000000024 (ops 115-119)
I20260812 06:19:45.538903 19571 log.cc:1079] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/811e4c330f774f76861443f23f90c2c6/wal-000000025 (ops 120-124)
I20260812 06:19:45.538946 19571 log.cc:1079] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/811e4c330f774f76861443f23f90c2c6/wal-000000026 (ops 125-128)
I20260812 06:19:45.565402 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: LogGCOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.027s	user 0.003s	sys 0.022s Metrics: {}
I20260812 06:19:45.565979 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=3.181125
I20260812 06:19:45.591416 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.025s	user 0.007s	sys 0.011s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7984,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:45.591958 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=2.188937
I20260812 06:19:45.602926 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4131,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:45.603416 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling MajorDeltaCompactionOp(811e4c330f774f76861443f23f90c2c6): perf score=1.000000
I20260812 06:19:45.823366 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: MajorDeltaCompactionOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.220s	user 0.133s	sys 0.084s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877326,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2662,"lbm_read_time_us":15347,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35871,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9984,"thread_start_us":96,"threads_started":1,"update_count":3000}
I20260812 06:19:45.823990 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=14.095187
I20260812 06:19:45.883865 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.060s	user 0.026s	sys 0.028s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24290,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:45.884446 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling MajorDeltaCompactionOp(811e4c330f774f76861443f23f90c2c6): perf score=1.000000
I20260812 06:19:46.035287 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: MajorDeltaCompactionOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.151s	user 0.111s	sys 0.028s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672159,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":394,"lbm_read_time_us":8911,"lbm_reads_lt_1ms":463,"lbm_write_time_us":23374,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:19:46.035936 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling UndoDeltaBlockGCOp(811e4c330f774f76861443f23f90c2c6): 462 bytes on disk
I20260812 06:19:46.036514 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: UndoDeltaBlockGCOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":105,"lbm_reads_lt_1ms":4}
I20260812 06:19:46.037359 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=14.095187
I20260812 06:19:46.089761 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.052s	user 0.020s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20739,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:46.090348 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=2.188937
I20260812 06:19:46.103348 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.013s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4830,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.104247 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling MajorDeltaCompactionOp(811e4c330f774f76861443f23f90c2c6): perf score=1.000000
I20260812 06:19:46.324987 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: MajorDeltaCompactionOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.221s	user 0.121s	sys 0.084s 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":452,"lbm_read_time_us":12703,"lbm_reads_lt_1ms":572,"lbm_write_time_us":37065,"lbm_writes_lt_1ms":543,"mutex_wait_us":78,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:46.325634 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=14.095187
I20260812 06:19:46.383003 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.057s	user 0.034s	sys 0.011s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20430,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:46.383605 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=2.188937
I20260812 06:19:46.394505 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4276,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.395299 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling MajorDeltaCompactionOp(811e4c330f774f76861443f23f90c2c6): perf score=1.000000
I20260812 06:19:46.558734 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: MajorDeltaCompactionOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.163s	user 0.121s	sys 0.035s 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":393,"lbm_read_time_us":11394,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29827,"lbm_writes_lt_1ms":543,"mutex_wait_us":64,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2500}
I20260812 06:19:46.559538 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=11.118625
I20260812 06:19:46.592022 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.032s	user 0.023s	sys 0.008s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":13537,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:46.592696 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=2.188937
I20260812 06:19:46.625133 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.032s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5874,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:46.625639 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=2.188937
I20260812 06:19:46.636772 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4313,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.637360 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling MajorDeltaCompactionOp(811e4c330f774f76861443f23f90c2c6): perf score=1.000000
I20260812 06:19:46.799038 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: MajorDeltaCompactionOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.161s	user 0.133s	sys 0.028s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774797,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1130,"lbm_read_time_us":10695,"lbm_reads_lt_1ms":573,"lbm_write_time_us":35938,"lbm_writes_lt_1ms":543,"mutex_wait_us":355,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":2500}
I20260812 06:19:46.800031 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=11.118625
I20260812 06:19:46.842486 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.042s	user 0.017s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17875,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:19:46.843122 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=2.188937
I20260812 06:19:46.860872 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.018s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":4965,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.861670 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=2.188937
I20260812 06:19:46.872561 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4054,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:46.873108 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling MajorDeltaCompactionOp(811e4c330f774f76861443f23f90c2c6): perf score=1.000000
I20260812 06:19:47.026990 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: MajorDeltaCompactionOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.154s	user 0.106s	sys 0.048s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":217,"lbm_read_time_us":11517,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32173,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:47.029804 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=11.118625
I20260812 06:19:47.070238 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.040s	user 0.022s	sys 0.015s Metrics: {"bytes_written":12717738,"delete_count":0,"lbm_write_time_us":18232,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:19:47.071014 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=2.188937
I20260812 06:19:47.087142 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.014s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4399,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:47.087666 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=2.188937
I20260812 06:19:47.097441 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.010s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3543,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:47.097990 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushMRSOp(811e4c330f774f76861443f23f90c2c6): perf score=1.000000
I20260812 06:19:47.134042 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushMRSOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.036s	user 0.034s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":85,"dirs.run_cpu_time_us":298,"dirs.run_wall_time_us":1481,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2009,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:47.135154 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling LogGCOp(811e4c330f774f76861443f23f90c2c6): free 129320774 bytes of WAL
I20260812 06:19:47.135475 19571 log_reader.cc:385] T 811e4c330f774f76861443f23f90c2c6: removed 13 log segments from log reader
I20260812 06:19:47.135555 19571 log.cc:1079] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/811e4c330f774f76861443f23f90c2c6/wal-000000027 (ops 129-133)
I20260812 06:19:47.135608 19571 log.cc:1079] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/811e4c330f774f76861443f23f90c2c6/wal-000000028 (ops 134-138)
I20260812 06:19:47.135731 19571 log.cc:1079] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/811e4c330f774f76861443f23f90c2c6/wal-000000029 (ops 139-143)
I20260812 06:19:47.135792 19571 log.cc:1079] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/811e4c330f774f76861443f23f90c2c6/wal-000000030 (ops 144-148)
I20260812 06:19:47.135838 19571 log.cc:1079] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/811e4c330f774f76861443f23f90c2c6/wal-000000031 (ops 149-152)
I20260812 06:19:47.135876 19571 log.cc:1079] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/811e4c330f774f76861443f23f90c2c6/wal-000000032 (ops 153-157)
I20260812 06:19:47.135923 19571 log.cc:1079] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/811e4c330f774f76861443f23f90c2c6/wal-000000033 (ops 158-162)
I20260812 06:19:47.136082 19571 log.cc:1079] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/811e4c330f774f76861443f23f90c2c6/wal-000000034 (ops 163-166)
I20260812 06:19:47.136148 19571 log.cc:1079] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/811e4c330f774f76861443f23f90c2c6/wal-000000035 (ops 167-171)
I20260812 06:19:47.136193 19571 log.cc:1079] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/811e4c330f774f76861443f23f90c2c6/wal-000000036 (ops 172-176)
I20260812 06:19:47.136232 19571 log.cc:1079] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/811e4c330f774f76861443f23f90c2c6/wal-000000037 (ops 177-181)
I20260812 06:19:47.136274 19571 log.cc:1079] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/811e4c330f774f76861443f23f90c2c6/wal-000000038 (ops 182-186)
I20260812 06:19:47.136312 19571 log.cc:1079] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/811e4c330f774f76861443f23f90c2c6/wal-000000039 (ops 187-191)
I20260812 06:19:47.165205 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: LogGCOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.030s	user 0.004s	sys 0.024s Metrics: {}
I20260812 06:19:47.165709 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=2.188937
I20260812 06:19:47.187850 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.022s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6305,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:47.188434 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling UndoDeltaBlockGCOp(811e4c330f774f76861443f23f90c2c6): 483 bytes on disk
I20260812 06:19:47.188871 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: UndoDeltaBlockGCOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:19:47.189364 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=2.188937
I20260812 06:19:47.200496 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4121,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:47.201207 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling MajorDeltaCompactionOp(811e4c330f774f76861443f23f90c2c6): perf score=1.000000
I20260812 06:19:47.327574 19454 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.170s	user 1.895s	sys 0.138s
I20260812 06:19:47.382107 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: MajorDeltaCompactionOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.181s	user 0.142s	sys 0.037s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979864,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"lbm_read_time_us":13898,"lbm_reads_lt_1ms":771,"lbm_write_time_us":37870,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":3500}
I20260812 06:19:47.382874 19639 maintenance_manager.cc:419] P 5283fd1a4367438880f8bcb67a20b16f: Scheduling FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6): perf score=10.126437
I20260812 06:19:47.417528 19454 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.089s	user 0.002s	sys 0.000s
I20260812 06:19:47.418231 19454 tablet_server.cc:179] TabletServer@127.18.255.129:0 shutting down...
I20260812 06:19:47.456948 19571 maintenance_manager.cc:643] P 5283fd1a4367438880f8bcb67a20b16f: FlushDeltaMemStoresOp(811e4c330f774f76861443f23f90c2c6) complete. Timing: real 0.074s	user 0.014s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13759,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:47.457860 19454 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:47.458467 19454 tablet_replica.cc:333] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f: stopping tablet replica
I20260812 06:19:47.458766 19454 raft_consensus.cc:2243] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:47.459088 19454 raft_consensus.cc:2272] T 811e4c330f774f76861443f23f90c2c6 P 5283fd1a4367438880f8bcb67a20b16f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:47.474205 19454 tablet_server.cc:196] TabletServer@127.18.255.129:0 shutdown complete.
I20260812 06:19:47.479859 19454 master.cc:562] Master@127.18.255.190:33447 shutting down...
I20260812 06:19:47.484131 19454 raft_consensus.cc:2243] T 00000000000000000000000000000000 P e6c420f7bec64fe98f4d54c1e665902e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:47.484375 19454 raft_consensus.cc:2272] T 00000000000000000000000000000000 P e6c420f7bec64fe98f4d54c1e665902e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:47.484469 19454 tablet_replica.cc:333] T 00000000000000000000000000000000 P e6c420f7bec64fe98f4d54c1e665902e: stopping tablet replica
I20260812 06:19:47.497303 19454 master.cc:584] Master@127.18.255.190:33447 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5744 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:47.589520 19454 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.18.255.190:44139
I20260812 06:19:47.590035 19454 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:47.592789 19678 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:47.593024 19679 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:47.593071 19454 server_base.cc:1061] running on GCE node
W20260812 06:19:47.593060 19681 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:47.593415 19454 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:47.593475 19454 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:47.593497 19454 hybrid_clock.cc:648] HybridClock initialized: now 1786515587593497 us; error 0 us; skew 500 ppm
I20260812 06:19:47.594363 19454 webserver.cc:533] Webserver started at http://127.18.255.190:37793/ using document root <none> and password file <none>
I20260812 06:19:47.594552 19454 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:47.594658 19454 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:47.594718 19454 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:47.595225 19454 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/master-0-root/instance:
uuid: "9f4415135a1d457f849b9aaac8d080db"
format_stamp: "Formatted at 2026-08-12 06:19:47 on dist-test-slave-dhph"
I20260812 06:19:47.596889 19454 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:47.597903 19687 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:47.598155 19454 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:47.598248 19454 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/master-0-root
uuid: "9f4415135a1d457f849b9aaac8d080db"
format_stamp: "Formatted at 2026-08-12 06:19:47 on dist-test-slave-dhph"
I20260812 06:19:47.598347 19454 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:47.608080 19454 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:47.608587 19454 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:47.614555 19454 rpc_server.cc:307] RPC server started. Bound to: 127.18.255.190:44139
I20260812 06:19:47.616181 19746 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.18.255.190:44139 every 8 connection(s)
I20260812 06:19:47.616370 19747 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:47.634196 19747 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 9f4415135a1d457f849b9aaac8d080db: Bootstrap starting.
I20260812 06:19:47.635270 19747 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 9f4415135a1d457f849b9aaac8d080db: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:47.636507 19747 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 9f4415135a1d457f849b9aaac8d080db: No bootstrap required, opened a new log
I20260812 06:19:47.636991 19747 raft_consensus.cc:359] T 00000000000000000000000000000000 P 9f4415135a1d457f849b9aaac8d080db [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9f4415135a1d457f849b9aaac8d080db" member_type: VOTER }
I20260812 06:19:47.637194 19747 raft_consensus.cc:385] T 00000000000000000000000000000000 P 9f4415135a1d457f849b9aaac8d080db [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:47.637221 19747 raft_consensus.cc:740] T 00000000000000000000000000000000 P 9f4415135a1d457f849b9aaac8d080db [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 9f4415135a1d457f849b9aaac8d080db, State: Initialized, Role: FOLLOWER
I20260812 06:19:47.637419 19747 consensus_queue.cc:260] T 00000000000000000000000000000000 P 9f4415135a1d457f849b9aaac8d080db [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: "9f4415135a1d457f849b9aaac8d080db" member_type: VOTER }
I20260812 06:19:47.637516 19747 raft_consensus.cc:399] T 00000000000000000000000000000000 P 9f4415135a1d457f849b9aaac8d080db [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:47.637542 19747 raft_consensus.cc:493] T 00000000000000000000000000000000 P 9f4415135a1d457f849b9aaac8d080db [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:47.637607 19747 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 9f4415135a1d457f849b9aaac8d080db [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:47.638399 19747 raft_consensus.cc:515] T 00000000000000000000000000000000 P 9f4415135a1d457f849b9aaac8d080db [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9f4415135a1d457f849b9aaac8d080db" member_type: VOTER }
I20260812 06:19:47.638525 19747 leader_election.cc:304] T 00000000000000000000000000000000 P 9f4415135a1d457f849b9aaac8d080db [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: 9f4415135a1d457f849b9aaac8d080db; no voters: 
I20260812 06:19:47.638793 19747 leader_election.cc:290] T 00000000000000000000000000000000 P 9f4415135a1d457f849b9aaac8d080db [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:47.639034 19750 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 9f4415135a1d457f849b9aaac8d080db [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:47.639235 19750 raft_consensus.cc:697] T 00000000000000000000000000000000 P 9f4415135a1d457f849b9aaac8d080db [term 1 LEADER]: Becoming Leader. State: Replica: 9f4415135a1d457f849b9aaac8d080db, State: Running, Role: LEADER
I20260812 06:19:47.639402 19750 consensus_queue.cc:237] T 00000000000000000000000000000000 P 9f4415135a1d457f849b9aaac8d080db [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: "9f4415135a1d457f849b9aaac8d080db" member_type: VOTER }
I20260812 06:19:47.639408 19747 sys_catalog.cc:565] T 00000000000000000000000000000000 P 9f4415135a1d457f849b9aaac8d080db [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:47.640094 19752 sys_catalog.cc:455] T 00000000000000000000000000000000 P 9f4415135a1d457f849b9aaac8d080db [sys.catalog]: SysCatalogTable state changed. Reason: New leader 9f4415135a1d457f849b9aaac8d080db. Latest consensus state: current_term: 1 leader_uuid: "9f4415135a1d457f849b9aaac8d080db" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9f4415135a1d457f849b9aaac8d080db" member_type: VOTER } }
I20260812 06:19:47.640208 19752 sys_catalog.cc:458] T 00000000000000000000000000000000 P 9f4415135a1d457f849b9aaac8d080db [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:47.641299 19751 sys_catalog.cc:455] T 00000000000000000000000000000000 P 9f4415135a1d457f849b9aaac8d080db [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "9f4415135a1d457f849b9aaac8d080db" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9f4415135a1d457f849b9aaac8d080db" member_type: VOTER } }
I20260812 06:19:47.641419 19757 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:47.641428 19751 sys_catalog.cc:458] T 00000000000000000000000000000000 P 9f4415135a1d457f849b9aaac8d080db [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:47.641786 19454 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:47.642359 19757 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:47.644451 19757 catalog_manager.cc:1383] Generated new cluster ID: 4d52e1b4e26043da8c5355b8de6fcda5
I20260812 06:19:47.644520 19757 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:47.649266 19757 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:47.649848 19757 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:47.654807 19757 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 9f4415135a1d457f849b9aaac8d080db: Generated new TSK 0
I20260812 06:19:47.655018 19757 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:47.658340 19454 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:47.660877 19774 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:47.660909 19770 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:47.660967 19771 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:47.661485 19454 server_base.cc:1061] running on GCE node
I20260812 06:19:47.661708 19454 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:47.661758 19454 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:47.661774 19454 hybrid_clock.cc:648] HybridClock initialized: now 1786515587661774 us; error 0 us; skew 500 ppm
I20260812 06:19:47.662755 19454 webserver.cc:533] Webserver started at http://127.18.255.129:37365/ using document root <none> and password file <none>
I20260812 06:19:47.662904 19454 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:47.662950 19454 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:47.663010 19454 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:47.663383 19454 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root/instance:
uuid: "3c8f2b545bcb48058d63331737f44888"
format_stamp: "Formatted at 2026-08-12 06:19:47 on dist-test-slave-dhph"
I20260812 06:19:47.665100 19454 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:47.666313 19780 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:47.666699 19454 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:47.666783 19454 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root
uuid: "3c8f2b545bcb48058d63331737f44888"
format_stamp: "Formatted at 2026-08-12 06:19:47 on dist-test-slave-dhph"
I20260812 06:19:47.666864 19454 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:47.689316 19454 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:47.690263 19454 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:47.690646 19454 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:47.691222 19454 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:47.691262 19454 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:47.691296 19454 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:47.691360 19454 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:47.696200 19454 rpc_server.cc:307] RPC server started. Bound to: 127.18.255.129:37555
I20260812 06:19:47.696400 19854 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.18.255.129:37555 every 8 connection(s)
I20260812 06:19:47.710137 19855 heartbeater.cc:344] Connected to a master server at 127.18.255.190:44139
I20260812 06:19:47.710283 19855 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:47.710543 19855 heartbeater.cc:507] Master 127.18.255.190:44139 requested a full tablet report, sending...
I20260812 06:19:47.711484 19706 ts_manager.cc:194] Registered new tserver with Master: 3c8f2b545bcb48058d63331737f44888 (127.18.255.129:37555)
I20260812 06:19:47.711606 19454 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.014893051s
I20260812 06:19:47.712807 19706 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:40092
I20260812 06:19:47.720898 19706 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:40098:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:47.732213 19812 tablet_service.cc:1511] Processing CreateTablet for tablet cd82cfbb893d4f31a1c13d67f559444c (DEFAULT_TABLE table=heavy-update-compaction-test [id=91319c7f4f95434892648e74089ffd6a]), partition=
I20260812 06:19:47.732595 19812 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet cd82cfbb893d4f31a1c13d67f559444c. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:47.735726 19869 tablet_bootstrap.cc:492] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Bootstrap starting.
I20260812 06:19:47.736719 19869 tablet_bootstrap.cc:654] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:47.738178 19869 tablet_bootstrap.cc:492] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: No bootstrap required, opened a new log
I20260812 06:19:47.738337 19869 ts_tablet_manager.cc:1403] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:47.738893 19869 raft_consensus.cc:359] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3c8f2b545bcb48058d63331737f44888" member_type: VOTER last_known_addr { host: "127.18.255.129" port: 37555 } }
I20260812 06:19:47.739018 19869 raft_consensus.cc:385] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:47.739084 19869 raft_consensus.cc:740] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 3c8f2b545bcb48058d63331737f44888, State: Initialized, Role: FOLLOWER
I20260812 06:19:47.739248 19869 consensus_queue.cc:260] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888 [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: "3c8f2b545bcb48058d63331737f44888" member_type: VOTER last_known_addr { host: "127.18.255.129" port: 37555 } }
I20260812 06:19:47.739357 19869 raft_consensus.cc:399] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:47.739404 19869 raft_consensus.cc:493] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:47.739456 19869 raft_consensus.cc:3060] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:47.740250 19869 raft_consensus.cc:515] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3c8f2b545bcb48058d63331737f44888" member_type: VOTER last_known_addr { host: "127.18.255.129" port: 37555 } }
I20260812 06:19:47.740420 19869 leader_election.cc:304] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888 [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: 3c8f2b545bcb48058d63331737f44888; no voters: 
I20260812 06:19:47.740691 19869 leader_election.cc:290] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:47.740990 19872 raft_consensus.cc:2804] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:47.741065 19869 ts_tablet_manager.cc:1434] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:47.741192 19855 heartbeater.cc:499] Master 127.18.255.190:44139 was elected leader, sending a full tablet report...
I20260812 06:19:47.741195 19872 raft_consensus.cc:697] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888 [term 1 LEADER]: Becoming Leader. State: Replica: 3c8f2b545bcb48058d63331737f44888, State: Running, Role: LEADER
I20260812 06:19:47.741438 19872 consensus_queue.cc:237] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888 [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: "3c8f2b545bcb48058d63331737f44888" member_type: VOTER last_known_addr { host: "127.18.255.129" port: 37555 } }
I20260812 06:19:47.743038 19706 catalog_manager.cc:5719] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888 reported cstate change: term changed from 0 to 1, leader changed from <none> to 3c8f2b545bcb48058d63331737f44888 (127.18.255.129). New cstate: current_term: 1 leader_uuid: "3c8f2b545bcb48058d63331737f44888" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3c8f2b545bcb48058d63331737f44888" member_type: VOTER last_known_addr { host: "127.18.255.129" port: 37555 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:47.806639 19454 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.057s	user 0.024s	sys 0.000s
I20260812 06:19:47.947642 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushMRSOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=15.086190
I20260812 06:19:48.102313 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushMRSOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.154s	user 0.108s	sys 0.040s Metrics: {"bytes_written":11897249,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":93,"dirs.run_cpu_time_us":231,"dirs.run_wall_time_us":947,"drs_written":1,"lbm_read_time_us":99,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39819,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":9600,"update_count":1450}
I20260812 06:19:48.103223 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling LogGCOp(cd82cfbb893d4f31a1c13d67f559444c): free 20743880 bytes of WAL
I20260812 06:19:48.103504 19785 log_reader.cc:385] T cd82cfbb893d4f31a1c13d67f559444c: removed 2 log segments from log reader
I20260812 06:19:48.103579 19785 log.cc:1079] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/cd82cfbb893d4f31a1c13d67f559444c/wal-000000001 (ops 1-6)
I20260812 06:19:48.103641 19785 log.cc:1079] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/cd82cfbb893d4f31a1c13d67f559444c/wal-000000002 (ops 7-11)
I20260812 06:19:48.108346 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: LogGCOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:19:48.108825 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=2.188937
I20260812 06:19:48.124966 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.016s	user 0.005s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5876,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:48.125519 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling UndoDeltaBlockGCOp(cd82cfbb893d4f31a1c13d67f559444c): 12719218 bytes on disk
I20260812 06:19:48.126101 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: UndoDeltaBlockGCOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":126,"lbm_reads_lt_1ms":4}
I20260812 06:19:48.126720 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=1.000000
I20260812 06:19:48.283396 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.156s	user 0.132s	sys 0.024s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262036,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":985,"lbm_read_time_us":9776,"lbm_reads_lt_1ms":450,"lbm_write_time_us":27853,"lbm_writes_lt_1ms":433,"mutex_wait_us":42,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":6400,"thread_start_us":411,"threads_started":5,"update_count":1950}
I20260812 06:19:48.284003 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=10.126437
I20260812 06:19:48.319268 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.035s	user 0.024s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14630,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:48.319823 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=2.188937
I20260812 06:19:48.330459 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4012,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:48.330979 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=1.000000
I20260812 06:19:48.476018 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.145s	user 0.112s	sys 0.030s 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":241,"lbm_read_time_us":10450,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26595,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":28160,"update_count":2000}
I20260812 06:19:48.476681 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=10.126437
I20260812 06:19:48.520210 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.043s	user 0.023s	sys 0.017s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14296,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:48.521064 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=1.000000
I20260812 06:19:48.664151 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.143s	user 0.092s	sys 0.048s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569747,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":424,"lbm_read_time_us":8989,"lbm_reads_lt_1ms":363,"lbm_write_time_us":23579,"lbm_writes_lt_1ms":343,"mutex_wait_us":1202,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":1500}
I20260812 06:19:48.664911 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=10.126437
I20260812 06:19:48.705108 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.040s	user 0.013s	sys 0.024s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16738,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:48.705721 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=2.188937
I20260812 06:19:48.719794 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4887,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:48.720449 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=1.000000
I20260812 06:19:48.864298 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.144s	user 0.113s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":208,"lbm_read_time_us":11345,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26488,"lbm_writes_lt_1ms":443,"mutex_wait_us":73,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":2000}
I20260812 06:19:48.864935 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=10.126437
I20260812 06:19:48.917608 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.052s	user 0.019s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19314,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:48.918196 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=2.188937
I20260812 06:19:48.932196 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4503,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:48.932723 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=1.000000
I20260812 06:19:49.081485 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.149s	user 0.120s	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":824,"lbm_read_time_us":10272,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30468,"lbm_writes_lt_1ms":443,"mutex_wait_us":91,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":49664,"update_count":2000}
I20260812 06:19:49.082223 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=10.126437
I20260812 06:19:49.134531 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.052s	user 0.022s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17660,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:49.135251 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=2.188937
I20260812 06:19:49.149060 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.014s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5068,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.149612 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=1.000000
I20260812 06:19:49.314826 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.165s	user 0.132s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":216,"lbm_read_time_us":10908,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26535,"lbm_writes_lt_1ms":443,"mutex_wait_us":106,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2000}
I20260812 06:19:49.315454 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=10.126437
I20260812 06:19:49.351454 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.036s	user 0.023s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14296,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:49.352273 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=1.000000
I20260812 06:19:49.466779 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.114s	user 0.087s	sys 0.025s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":816,"lbm_read_time_us":6193,"lbm_reads_lt_1ms":363,"lbm_write_time_us":21390,"lbm_writes_lt_1ms":343,"mutex_wait_us":272,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":17280,"update_count":1500}
I20260812 06:19:49.467562 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=10.126437
I20260812 06:19:49.516552 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.049s	user 0.017s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15313,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:49.517269 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=2.188937
I20260812 06:19:49.529691 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4436,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.530251 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushMRSOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=1.000000
I20260812 06:19:49.565572 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushMRSOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.035s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":92,"dirs.run_cpu_time_us":253,"dirs.run_wall_time_us":1834,"drs_written":1,"lbm_read_time_us":81,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1793,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:49.566478 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling LogGCOp(cd82cfbb893d4f31a1c13d67f559444c): free 112239312 bytes of WAL
I20260812 06:19:49.566849 19785 log_reader.cc:385] T cd82cfbb893d4f31a1c13d67f559444c: removed 11 log segments from log reader
I20260812 06:19:49.566933 19785 log.cc:1079] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/cd82cfbb893d4f31a1c13d67f559444c/wal-000000003 (ops 12-16)
I20260812 06:19:49.566989 19785 log.cc:1079] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/cd82cfbb893d4f31a1c13d67f559444c/wal-000000004 (ops 17-21)
I20260812 06:19:49.567052 19785 log.cc:1079] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/cd82cfbb893d4f31a1c13d67f559444c/wal-000000005 (ops 22-26)
I20260812 06:19:49.567093 19785 log.cc:1079] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/cd82cfbb893d4f31a1c13d67f559444c/wal-000000006 (ops 27-30)
I20260812 06:19:49.567142 19785 log.cc:1079] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/cd82cfbb893d4f31a1c13d67f559444c/wal-000000007 (ops 31-35)
I20260812 06:19:49.567215 19785 log.cc:1079] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/cd82cfbb893d4f31a1c13d67f559444c/wal-000000008 (ops 36-40)
I20260812 06:19:49.567272 19785 log.cc:1079] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/cd82cfbb893d4f31a1c13d67f559444c/wal-000000009 (ops 41-45)
I20260812 06:19:49.567338 19785 log.cc:1079] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/cd82cfbb893d4f31a1c13d67f559444c/wal-000000010 (ops 46-50)
I20260812 06:19:49.567378 19785 log.cc:1079] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/cd82cfbb893d4f31a1c13d67f559444c/wal-000000011 (ops 51-55)
I20260812 06:19:49.567418 19785 log.cc:1079] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/cd82cfbb893d4f31a1c13d67f559444c/wal-000000012 (ops 56-60)
I20260812 06:19:49.567443 19785 log.cc:1079] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/cd82cfbb893d4f31a1c13d67f559444c/wal-000000013 (ops 61-65)
I20260812 06:19:49.593030 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: LogGCOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.026s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:19:49.593540 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=3.181125
I20260812 06:19:49.606994 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.013s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":5388,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:49.607470 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling LogGCOp(cd82cfbb893d4f31a1c13d67f559444c): free 12017932 bytes of WAL
I20260812 06:19:49.607702 19785 log_reader.cc:385] T cd82cfbb893d4f31a1c13d67f559444c: removed 1 log segments from log reader
I20260812 06:19:49.607751 19785 log.cc:1079] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/cd82cfbb893d4f31a1c13d67f559444c/wal-000000014 (ops 66-70)
I20260812 06:19:49.610236 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: LogGCOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:49.610654 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=2.188937
I20260812 06:19:49.623878 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4361,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:49.624540 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling UndoDeltaBlockGCOp(cd82cfbb893d4f31a1c13d67f559444c): 462 bytes on disk
I20260812 06:19:49.625131 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: UndoDeltaBlockGCOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:19:49.625777 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=1.000000
I20260812 06:19:49.822995 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.197s	user 0.131s	sys 0.060s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877325,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":670,"lbm_read_time_us":13248,"lbm_reads_lt_1ms":666,"lbm_write_time_us":34884,"lbm_writes_lt_1ms":643,"mutex_wait_us":53,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6912,"thread_start_us":89,"threads_started":1,"update_count":3000}
I20260812 06:19:49.823774 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=14.095187
I20260812 06:19:49.896651 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.073s	user 0.051s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":35640,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:19:49.897210 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=2.188937
I20260812 06:19:49.915406 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.018s	user 0.001s	sys 0.016s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6870,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.916205 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=1.000000
I20260812 06:19:50.083076 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.167s	user 0.115s	sys 0.043s 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":390,"lbm_read_time_us":9914,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30973,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16384,"update_count":2500}
I20260812 06:19:50.083954 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=14.095187
I20260812 06:19:50.132398 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.048s	user 0.030s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21764,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:50.133116 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=1.000000
I20260812 06:19:50.293493 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.160s	user 0.113s	sys 0.044s 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":161,"lbm_read_time_us":13255,"lbm_reads_lt_1ms":467,"lbm_write_time_us":26109,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14592,"update_count":2000}
I20260812 06:19:50.294198 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=10.126437
I20260812 06:19:50.335073 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.041s	user 0.015s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16801,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:50.335645 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=2.188937
I20260812 06:19:50.350234 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5689,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:50.350971 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=1.000000
I20260812 06:19:50.496389 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.145s	user 0.118s	sys 0.027s 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":873,"lbm_read_time_us":10045,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29255,"lbm_writes_lt_1ms":443,"mutex_wait_us":340,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2000}
I20260812 06:19:50.497136 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=10.126437
I20260812 06:19:50.543167 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.046s	user 0.026s	sys 0.013s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17165,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:50.543735 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=2.188937
I20260812 06:19:50.554895 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4387,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:50.555536 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=1.000000
I20260812 06:19:50.683997 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.128s	user 0.116s	sys 0.012s 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":643,"lbm_read_time_us":9423,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23832,"lbm_writes_lt_1ms":443,"mutex_wait_us":91,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2000}
I20260812 06:19:50.684780 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=10.126437
I20260812 06:19:50.723753 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.039s	user 0.022s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17289,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:50.724310 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=1.000000
I20260812 06:19:50.835423 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.111s	user 0.084s	sys 0.024s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1109,"lbm_read_time_us":6292,"lbm_reads_lt_1ms":363,"lbm_write_time_us":24056,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":342,"mutex_wait_us":414,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":1500}
I20260812 06:19:50.836305 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=10.126437
I20260812 06:19:50.885340 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.049s	user 0.012s	sys 0.032s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20540,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:50.885972 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=2.188937
I20260812 06:19:50.898130 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4386,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:50.898883 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=1.000000
I20260812 06:19:51.060917 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.162s	user 0.122s	sys 0.039s 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":1650,"lbm_read_time_us":9244,"lbm_reads_lt_1ms":472,"lbm_write_time_us":32512,"lbm_writes_lt_1ms":443,"mutex_wait_us":327,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":26368,"update_count":2000}
I20260812 06:19:51.061683 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=10.126437
I20260812 06:19:51.121650 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.060s	user 0.024s	sys 0.020s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":20427,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:51.122287 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=2.188937
I20260812 06:19:51.140221 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.018s	user 0.007s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6798,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.140976 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushMRSOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=1.000000
I20260812 06:19:51.177296 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushMRSOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.036s	user 0.030s	sys 0.004s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":236,"dirs.run_wall_time_us":1705,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2400,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:51.178215 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling LogGCOp(cd82cfbb893d4f31a1c13d67f559444c): free 112692366 bytes of WAL
I20260812 06:19:51.178504 19785 log_reader.cc:385] T cd82cfbb893d4f31a1c13d67f559444c: removed 11 log segments from log reader
I20260812 06:19:51.178557 19785 log.cc:1079] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/cd82cfbb893d4f31a1c13d67f559444c/wal-000000015 (ops 71-75)
I20260812 06:19:51.178643 19785 log.cc:1079] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/cd82cfbb893d4f31a1c13d67f559444c/wal-000000016 (ops 76-80)
I20260812 06:19:51.178694 19785 log.cc:1079] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/cd82cfbb893d4f31a1c13d67f559444c/wal-000000017 (ops 81-85)
I20260812 06:19:51.178766 19785 log.cc:1079] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/cd82cfbb893d4f31a1c13d67f559444c/wal-000000018 (ops 86-90)
I20260812 06:19:51.178810 19785 log.cc:1079] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/cd82cfbb893d4f31a1c13d67f559444c/wal-000000019 (ops 91-95)
I20260812 06:19:51.178881 19785 log.cc:1079] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/cd82cfbb893d4f31a1c13d67f559444c/wal-000000020 (ops 96-100)
I20260812 06:19:51.178930 19785 log.cc:1079] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/cd82cfbb893d4f31a1c13d67f559444c/wal-000000021 (ops 101-105)
I20260812 06:19:51.178974 19785 log.cc:1079] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/cd82cfbb893d4f31a1c13d67f559444c/wal-000000022 (ops 106-110)
I20260812 06:19:51.179021 19785 log.cc:1079] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/cd82cfbb893d4f31a1c13d67f559444c/wal-000000023 (ops 111-115)
I20260812 06:19:51.179065 19785 log.cc:1079] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/cd82cfbb893d4f31a1c13d67f559444c/wal-000000024 (ops 116-120)
I20260812 06:19:51.179108 19785 log.cc:1079] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/cd82cfbb893d4f31a1c13d67f559444c/wal-000000025 (ops 121-125)
I20260812 06:19:51.207798 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: LogGCOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.029s	user 0.001s	sys 0.027s Metrics: {}
I20260812 06:19:51.208249 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=3.181125
I20260812 06:19:51.223564 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":6168,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:51.224114 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=2.188937
I20260812 06:19:51.237087 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.013s	user 0.002s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4407,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:51.237843 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling UndoDeltaBlockGCOp(cd82cfbb893d4f31a1c13d67f559444c): 473 bytes on disk
I20260812 06:19:51.238449 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: UndoDeltaBlockGCOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:19:51.239185 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=1.000000
I20260812 06:19:51.438060 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.199s	user 0.127s	sys 0.059s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877327,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":829,"lbm_read_time_us":10528,"lbm_reads_lt_1ms":666,"lbm_write_time_us":41352,"lbm_writes_lt_1ms":643,"mutex_wait_us":97,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4736,"thread_start_us":91,"threads_started":1,"update_count":3000}
I20260812 06:19:51.438900 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=14.095187
I20260812 06:19:51.495211 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.056s	user 0.041s	sys 0.014s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25184,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:51.495777 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=2.188937
I20260812 06:19:51.508641 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.013s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4872,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.509274 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=1.000000
I20260812 06:19:51.679325 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.170s	user 0.137s	sys 0.031s 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":344,"lbm_read_time_us":11759,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34196,"lbm_writes_lt_1ms":543,"mutex_wait_us":45,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2500}
I20260812 06:19:51.680127 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=11.118625
I20260812 06:19:51.721129 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.041s	user 0.012s	sys 0.025s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":19742,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:19:51.721727 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=2.188937
I20260812 06:19:51.739454 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.018s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4510,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.740119 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=2.188937
I20260812 06:19:51.752579 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.012s	user 0.005s	sys 0.006s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4251,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:51.753396 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=1.000000
I20260812 06:19:51.898772 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.143s	user 0.094s	sys 0.049s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":305,"lbm_read_time_us":9986,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30080,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2500}
I20260812 06:19:51.899619 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=10.126437
I20260812 06:19:51.937068 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.037s	user 0.021s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16351,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:51.937955 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=2.188937
I20260812 06:19:51.954758 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.017s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6271,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.955346 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=1.000000
I20260812 06:19:52.098743 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.143s	user 0.114s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":880,"lbm_read_time_us":7577,"lbm_reads_lt_1ms":468,"lbm_write_time_us":27153,"lbm_writes_lt_1ms":443,"mutex_wait_us":401,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16896,"update_count":2000}
I20260812 06:19:52.099560 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=10.126437
I20260812 06:19:52.138865 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.039s	user 0.028s	sys 0.003s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13237,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:52.139524 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=2.188937
I20260812 06:19:52.156313 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.017s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6144,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.157115 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=1.000000
I20260812 06:19:52.291785 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.134s	user 0.102s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":686,"lbm_read_time_us":11253,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24817,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":2000}
I20260812 06:19:52.292312 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=10.126437
I20260812 06:19:52.348469 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.056s	user 0.028s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16410,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:52.349221 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=2.188937
I20260812 06:19:52.360468 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4369,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.361104 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=1.000000
I20260812 06:19:52.521586 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.160s	user 0.083s	sys 0.072s 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":989,"lbm_read_time_us":10959,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25001,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":2000}
I20260812 06:19:52.522265 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=10.126437
I20260812 06:19:52.566958 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.044s	user 0.021s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14206,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:52.567520 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=2.188937
I20260812 06:19:52.579620 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4382,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.580448 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushMRSOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=1.000000
I20260812 06:19:52.615358 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushMRSOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.035s	user 0.027s	sys 0.004s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":191,"dirs.run_wall_time_us":1697,"drs_written":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1543,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:52.616175 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling LogGCOp(cd82cfbb893d4f31a1c13d67f559444c): free 120100568 bytes of WAL
I20260812 06:19:52.616449 19785 log_reader.cc:385] T cd82cfbb893d4f31a1c13d67f559444c: removed 12 log segments from log reader
I20260812 06:19:52.616520 19785 log.cc:1079] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/cd82cfbb893d4f31a1c13d67f559444c/wal-000000026 (ops 126-130)
I20260812 06:19:52.616575 19785 log.cc:1079] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/cd82cfbb893d4f31a1c13d67f559444c/wal-000000027 (ops 131-135)
I20260812 06:19:52.616636 19785 log.cc:1079] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/cd82cfbb893d4f31a1c13d67f559444c/wal-000000028 (ops 136-140)
I20260812 06:19:52.616675 19785 log.cc:1079] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/cd82cfbb893d4f31a1c13d67f559444c/wal-000000029 (ops 141-144)
I20260812 06:19:52.616715 19785 log.cc:1079] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/cd82cfbb893d4f31a1c13d67f559444c/wal-000000030 (ops 145-149)
I20260812 06:19:52.616753 19785 log.cc:1079] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/cd82cfbb893d4f31a1c13d67f559444c/wal-000000031 (ops 150-154)
I20260812 06:19:52.616791 19785 log.cc:1079] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/cd82cfbb893d4f31a1c13d67f559444c/wal-000000032 (ops 155-158)
I20260812 06:19:52.616827 19785 log.cc:1079] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/cd82cfbb893d4f31a1c13d67f559444c/wal-000000033 (ops 159-163)
I20260812 06:19:52.616865 19785 log.cc:1079] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/cd82cfbb893d4f31a1c13d67f559444c/wal-000000034 (ops 164-168)
I20260812 06:19:52.616902 19785 log.cc:1079] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/cd82cfbb893d4f31a1c13d67f559444c/wal-000000035 (ops 169-172)
I20260812 06:19:52.616938 19785 log.cc:1079] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/cd82cfbb893d4f31a1c13d67f559444c/wal-000000036 (ops 173-177)
I20260812 06:19:52.616976 19785 log.cc:1079] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: Deleting log segment in path: /tmp/dist-test-taskKZdgf6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515581834046-19454-0/minicluster-data/ts-0-root/wals/cd82cfbb893d4f31a1c13d67f559444c/wal-000000037 (ops 178-182)
I20260812 06:19:52.644886 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: LogGCOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:52.645452 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling UndoDeltaBlockGCOp(cd82cfbb893d4f31a1c13d67f559444c): 447 bytes on disk
I20260812 06:19:52.645972 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: UndoDeltaBlockGCOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":79,"lbm_reads_lt_1ms":4}
I20260812 06:19:52.646765 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=3.181125
I20260812 06:19:52.658713 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4711,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:52.659188 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=2.188937
I20260812 06:19:52.678995 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.020s	user 0.004s	sys 0.015s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3905,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:52.679800 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=1.000000
I20260812 06:19:52.909399 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.229s	user 0.175s	sys 0.052s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877327,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":803,"lbm_read_time_us":13859,"lbm_reads_lt_1ms":674,"lbm_write_time_us":41037,"lbm_writes_lt_1ms":643,"mutex_wait_us":360,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":384,"thread_start_us":109,"threads_started":1,"update_count":3000}
I20260812 06:19:52.910234 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=14.095187
I20260812 06:19:52.972757 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.062s	user 0.022s	sys 0.038s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22289,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:19:52.973508 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=2.188937
I20260812 06:19:52.984992 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: FlushDeltaMemStoresOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4564,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.985594 19856 maintenance_manager.cc:419] P 3c8f2b545bcb48058d63331737f44888: Scheduling MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c): perf score=1.000000
I20260812 06:19:53.079372 19454 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.273s	user 1.971s	sys 0.185s
I20260812 06:19:53.152762 19454 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.073s	user 0.001s	sys 0.000s
I20260812 06:19:53.153314 19454 tablet_server.cc:179] TabletServer@127.18.255.129:0 shutting down...
I20260812 06:19:53.160060 19785 maintenance_manager.cc:643] P 3c8f2b545bcb48058d63331737f44888: MajorDeltaCompactionOp(cd82cfbb893d4f31a1c13d67f559444c) complete. Timing: real 0.174s	user 0.114s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":310,"lbm_read_time_us":13639,"lbm_reads_lt_1ms":568,"lbm_write_time_us":27005,"lbm_writes_lt_1ms":543,"mutex_wait_us":71,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2500}
I20260812 06:19:53.160825 19454 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:53.161090 19454 tablet_replica.cc:333] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888: stopping tablet replica
I20260812 06:19:53.161247 19454 raft_consensus.cc:2243] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:53.161432 19454 raft_consensus.cc:2272] T cd82cfbb893d4f31a1c13d67f559444c P 3c8f2b545bcb48058d63331737f44888 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:53.168366 19454 tablet_server.cc:196] TabletServer@127.18.255.129:0 shutdown complete.
I20260812 06:19:53.206964 19454 master.cc:562] Master@127.18.255.190:44139 shutting down...
I20260812 06:19:53.211267 19454 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 9f4415135a1d457f849b9aaac8d080db [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:53.211522 19454 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 9f4415135a1d457f849b9aaac8d080db [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:53.211628 19454 tablet_replica.cc:333] T 00000000000000000000000000000000 P 9f4415135a1d457f849b9aaac8d080db: stopping tablet replica
I20260812 06:19:53.224915 19454 master.cc:584] Master@127.18.255.190:44139 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5724 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11470 ms total)

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