[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:17:39.806879 24170 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.23.154.190:44201
I20260812 06:17:39.808022 24170 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:17:39.808707 24170 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:39.815694 24178 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:39.815701 24176 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:39.815960 24170 server_base.cc:1061] running on GCE node
W20260812 06:17:39.816017 24175 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:39.816577 24170 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:39.816735 24170 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:39.816785 24170 hybrid_clock.cc:648] HybridClock initialized: now 1786515459816782 us; error 0 us; skew 500 ppm
I20260812 06:17:39.818794 24170 webserver.cc:533] Webserver started at http://127.23.154.190:41007/ using document root <none> and password file <none>
I20260812 06:17:39.819458 24170 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:39.819522 24170 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:39.819813 24170 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:39.821659 24170 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/master-0-root/instance:
uuid: "96b29d88240143dca57e5741d6455f75"
format_stamp: "Formatted at 2026-08-12 06:17:39 on dist-test-slave-njxd"
I20260812 06:17:39.825675 24170 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.001s	sys 0.003s
I20260812 06:17:39.828060 24184 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:39.829155 24170 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:17:39.829295 24170 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/master-0-root
uuid: "96b29d88240143dca57e5741d6455f75"
format_stamp: "Formatted at 2026-08-12 06:17:39 on dist-test-slave-njxd"
I20260812 06:17:39.829416 24170 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:39.876824 24170 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:39.877655 24170 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:17:39.877863 24170 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:39.886571 24170 rpc_server.cc:307] RPC server started. Bound to: 127.23.154.190:44201
I20260812 06:17:39.886581 24242 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.154.190:44201 every 8 connection(s)
I20260812 06:17:39.889245 24243 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:39.895553 24243 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 96b29d88240143dca57e5741d6455f75: Bootstrap starting.
I20260812 06:17:39.898236 24243 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 96b29d88240143dca57e5741d6455f75: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:39.899348 24243 log.cc:826] T 00000000000000000000000000000000 P 96b29d88240143dca57e5741d6455f75: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:39.901427 24243 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 96b29d88240143dca57e5741d6455f75: No bootstrap required, opened a new log
I20260812 06:17:39.904575 24243 raft_consensus.cc:359] T 00000000000000000000000000000000 P 96b29d88240143dca57e5741d6455f75 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "96b29d88240143dca57e5741d6455f75" member_type: VOTER }
I20260812 06:17:39.904793 24243 raft_consensus.cc:385] T 00000000000000000000000000000000 P 96b29d88240143dca57e5741d6455f75 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:39.904889 24243 raft_consensus.cc:740] T 00000000000000000000000000000000 P 96b29d88240143dca57e5741d6455f75 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 96b29d88240143dca57e5741d6455f75, State: Initialized, Role: FOLLOWER
I20260812 06:17:39.905620 24243 consensus_queue.cc:260] T 00000000000000000000000000000000 P 96b29d88240143dca57e5741d6455f75 [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: "96b29d88240143dca57e5741d6455f75" member_type: VOTER }
I20260812 06:17:39.905813 24243 raft_consensus.cc:399] T 00000000000000000000000000000000 P 96b29d88240143dca57e5741d6455f75 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:39.905920 24243 raft_consensus.cc:493] T 00000000000000000000000000000000 P 96b29d88240143dca57e5741d6455f75 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:39.906080 24243 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 96b29d88240143dca57e5741d6455f75 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:39.907013 24243 raft_consensus.cc:515] T 00000000000000000000000000000000 P 96b29d88240143dca57e5741d6455f75 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "96b29d88240143dca57e5741d6455f75" member_type: VOTER }
I20260812 06:17:39.907527 24243 leader_election.cc:304] T 00000000000000000000000000000000 P 96b29d88240143dca57e5741d6455f75 [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: 96b29d88240143dca57e5741d6455f75; no voters: 
I20260812 06:17:39.907909 24243 leader_election.cc:290] T 00000000000000000000000000000000 P 96b29d88240143dca57e5741d6455f75 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:39.908082 24246 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 96b29d88240143dca57e5741d6455f75 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:39.908378 24246 raft_consensus.cc:697] T 00000000000000000000000000000000 P 96b29d88240143dca57e5741d6455f75 [term 1 LEADER]: Becoming Leader. State: Replica: 96b29d88240143dca57e5741d6455f75, State: Running, Role: LEADER
I20260812 06:17:39.908905 24246 consensus_queue.cc:237] T 00000000000000000000000000000000 P 96b29d88240143dca57e5741d6455f75 [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: "96b29d88240143dca57e5741d6455f75" member_type: VOTER }
I20260812 06:17:39.909081 24243 sys_catalog.cc:565] T 00000000000000000000000000000000 P 96b29d88240143dca57e5741d6455f75 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:39.911231 24248 sys_catalog.cc:455] T 00000000000000000000000000000000 P 96b29d88240143dca57e5741d6455f75 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 96b29d88240143dca57e5741d6455f75. Latest consensus state: current_term: 1 leader_uuid: "96b29d88240143dca57e5741d6455f75" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "96b29d88240143dca57e5741d6455f75" member_type: VOTER } }
I20260812 06:17:39.911275 24247 sys_catalog.cc:455] T 00000000000000000000000000000000 P 96b29d88240143dca57e5741d6455f75 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "96b29d88240143dca57e5741d6455f75" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "96b29d88240143dca57e5741d6455f75" member_type: VOTER } }
I20260812 06:17:39.911410 24247 sys_catalog.cc:458] T 00000000000000000000000000000000 P 96b29d88240143dca57e5741d6455f75 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:39.911412 24248 sys_catalog.cc:458] T 00000000000000000000000000000000 P 96b29d88240143dca57e5741d6455f75 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:39.911800 24170 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:39.911844 24261 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:39.914319 24261 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:39.919962 24261 catalog_manager.cc:1383] Generated new cluster ID: 098e99b854734587aefb255023d7bb83
I20260812 06:17:39.920065 24261 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:39.933902 24261 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:39.935202 24261 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:39.945413 24261 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 96b29d88240143dca57e5741d6455f75: Generated new TSK 0
I20260812 06:17:39.946345 24261 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:39.976958 24170 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:39.980173 24266 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:39.980293 24267 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:39.980293 24269 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:39.980887 24170 server_base.cc:1061] running on GCE node
I20260812 06:17:39.981120 24170 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:39.981163 24170 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:39.981178 24170 hybrid_clock.cc:648] HybridClock initialized: now 1786515459981179 us; error 0 us; skew 500 ppm
I20260812 06:17:39.982244 24170 webserver.cc:533] Webserver started at http://127.23.154.129:42583/ using document root <none> and password file <none>
I20260812 06:17:39.982499 24170 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:39.982577 24170 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:39.982666 24170 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:39.983187 24170 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/instance:
uuid: "6403323564314e57961bb66ea2659917"
format_stamp: "Formatted at 2026-08-12 06:17:39 on dist-test-slave-njxd"
I20260812 06:17:39.985703 24170 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.003s	sys 0.001s
I20260812 06:17:39.986951 24274 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:39.987227 24170 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:39.987309 24170 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root
uuid: "6403323564314e57961bb66ea2659917"
format_stamp: "Formatted at 2026-08-12 06:17:39 on dist-test-slave-njxd"
I20260812 06:17:39.987416 24170 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:40.021003 24170 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:40.021495 24170 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:40.022092 24170 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:40.023033 24170 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:40.023088 24170 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:40.023161 24170 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:40.023207 24170 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:40.030192 24170 rpc_server.cc:307] RPC server started. Bound to: 127.23.154.129:42847
I20260812 06:17:40.030267 24347 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.154.129:42847 every 8 connection(s)
I20260812 06:17:40.044117 24348 heartbeater.cc:344] Connected to a master server at 127.23.154.190:44201
I20260812 06:17:40.044432 24348 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:40.044925 24348 heartbeater.cc:507] Master 127.23.154.190:44201 requested a full tablet report, sending...
I20260812 06:17:40.046650 24203 ts_manager.cc:194] Registered new tserver with Master: 6403323564314e57961bb66ea2659917 (127.23.154.129:42847)
I20260812 06:17:40.046712 24170 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01583826s
I20260812 06:17:40.048372 24203 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:35054
I20260812 06:17:40.057924 24203 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:35070:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:40.074221 24306 tablet_service.cc:1511] Processing CreateTablet for tablet b0622bdc099843449f11b5771172a65f (DEFAULT_TABLE table=heavy-update-compaction-test [id=b82ccc0e427c4e57b41034c8727a9d3e]), partition=
I20260812 06:17:40.074790 24306 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet b0622bdc099843449f11b5771172a65f. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:40.077688 24366 tablet_bootstrap.cc:492] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Bootstrap starting.
I20260812 06:17:40.079006 24366 tablet_bootstrap.cc:654] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:40.080497 24366 tablet_bootstrap.cc:492] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: No bootstrap required, opened a new log
I20260812 06:17:40.080636 24366 ts_tablet_manager.cc:1403] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:40.081257 24366 raft_consensus.cc:359] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6403323564314e57961bb66ea2659917" member_type: VOTER last_known_addr { host: "127.23.154.129" port: 42847 } }
I20260812 06:17:40.081391 24366 raft_consensus.cc:385] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:40.081421 24366 raft_consensus.cc:740] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6403323564314e57961bb66ea2659917, State: Initialized, Role: FOLLOWER
I20260812 06:17:40.081640 24366 consensus_queue.cc:260] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917 [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: "6403323564314e57961bb66ea2659917" member_type: VOTER last_known_addr { host: "127.23.154.129" port: 42847 } }
I20260812 06:17:40.081736 24366 raft_consensus.cc:399] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:40.081771 24366 raft_consensus.cc:493] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:40.081817 24366 raft_consensus.cc:3060] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:40.082811 24366 raft_consensus.cc:515] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6403323564314e57961bb66ea2659917" member_type: VOTER last_known_addr { host: "127.23.154.129" port: 42847 } }
I20260812 06:17:40.082960 24366 leader_election.cc:304] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917 [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: 6403323564314e57961bb66ea2659917; no voters: 
I20260812 06:17:40.083177 24366 leader_election.cc:290] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:40.083356 24368 raft_consensus.cc:2804] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:40.083478 24366 ts_tablet_manager.cc:1434] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:40.083775 24348 heartbeater.cc:499] Master 127.23.154.190:44201 was elected leader, sending a full tablet report...
I20260812 06:17:40.084101 24368 raft_consensus.cc:697] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917 [term 1 LEADER]: Becoming Leader. State: Replica: 6403323564314e57961bb66ea2659917, State: Running, Role: LEADER
I20260812 06:17:40.084270 24368 consensus_queue.cc:237] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917 [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: "6403323564314e57961bb66ea2659917" member_type: VOTER last_known_addr { host: "127.23.154.129" port: 42847 } }
I20260812 06:17:40.087450 24203 catalog_manager.cc:5719] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917 reported cstate change: term changed from 0 to 1, leader changed from <none> to 6403323564314e57961bb66ea2659917 (127.23.154.129). New cstate: current_term: 1 leader_uuid: "6403323564314e57961bb66ea2659917" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6403323564314e57961bb66ea2659917" member_type: VOTER last_known_addr { host: "127.23.154.129" port: 42847 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:40.156328 24170 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.061s	user 0.021s	sys 0.008s
I20260812 06:17:40.281533 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushMRSOp(b0622bdc099843449f11b5771172a65f): perf score=15.086190
I20260812 06:17:40.438539 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushMRSOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.157s	user 0.113s	sys 0.036s Metrics: {"bytes_written":11897249,"cfile_init":1,"compiler_manager_pool.queue_time_us":229,"delete_count":0,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":241,"dirs.run_wall_time_us":833,"drs_written":1,"lbm_read_time_us":101,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38212,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":154,"threads_started":1,"update_count":1450}
I20260812 06:17:40.439671 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling LogGCOp(b0622bdc099843449f11b5771172a65f): free 20743880 bytes of WAL
I20260812 06:17:40.439990 24279 log_reader.cc:385] T b0622bdc099843449f11b5771172a65f: removed 2 log segments from log reader
I20260812 06:17:40.440075 24279 log.cc:1079] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/b0622bdc099843449f11b5771172a65f/wal-000000001 (ops 1-6)
I20260812 06:17:40.440147 24279 log.cc:1079] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/b0622bdc099843449f11b5771172a65f/wal-000000002 (ops 7-11)
I20260812 06:17:40.444525 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: LogGCOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.005s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:40.444908 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling UndoDeltaBlockGCOp(b0622bdc099843449f11b5771172a65f): 12719216 bytes on disk
I20260812 06:17:40.445482 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: UndoDeltaBlockGCOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:17:40.445945 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=2.188937
I20260812 06:17:40.467264 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.021s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6570,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:40.467751 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f): perf score=1.000000
I20260812 06:17:40.607218 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.139s	user 0.103s	sys 0.036s 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":891,"lbm_read_time_us":7403,"lbm_reads_lt_1ms":450,"lbm_write_time_us":26904,"lbm_writes_lt_1ms":433,"peak_mem_usage":49238594,"reinsert_count":0,"thread_start_us":344,"threads_started":5,"update_count":1950}
I20260812 06:17:40.607873 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=10.126437
I20260812 06:17:40.652091 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.044s	user 0.015s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19240,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:17:40.652633 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=2.188937
I20260812 06:17:40.664469 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4234,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:40.665160 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f): perf score=1.000000
I20260812 06:17:40.794114 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.129s	user 0.114s	sys 0.014s 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":1280,"lbm_read_time_us":9695,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23913,"lbm_writes_lt_1ms":443,"mutex_wait_us":338,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":31488,"update_count":2000}
I20260812 06:17:40.794675 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=10.126437
I20260812 06:17:40.835954 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.041s	user 0.019s	sys 0.017s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16708,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:40.836560 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=2.188937
I20260812 06:17:40.848174 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4228,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:40.848726 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f): perf score=1.000000
I20260812 06:17:40.978197 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.129s	user 0.105s	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":244,"lbm_read_time_us":7964,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28080,"lbm_writes_lt_1ms":443,"mutex_wait_us":49,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:40.978893 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=10.126437
I20260812 06:17:41.035143 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.056s	user 0.024s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14917,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:41.035772 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=2.188937
I20260812 06:17:41.047330 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4360,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.047807 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f): perf score=1.000000
I20260812 06:17:41.212476 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.164s	user 0.116s	sys 0.048s 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":227,"lbm_read_time_us":11442,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29067,"lbm_writes_lt_1ms":443,"mutex_wait_us":57,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:41.213150 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=10.126437
I20260812 06:17:41.262051 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.049s	user 0.021s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15906,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:41.262624 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=2.188937
I20260812 06:17:41.274741 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4277,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.275401 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f): perf score=1.000000
I20260812 06:17:41.406497 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.131s	user 0.095s	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":1038,"lbm_read_time_us":8117,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26008,"lbm_writes_lt_1ms":443,"mutex_wait_us":299,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14336,"update_count":2000}
I20260812 06:17:41.407394 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=10.126437
I20260812 06:17:41.447043 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.039s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15796,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:41.447675 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=2.188937
I20260812 06:17:41.459406 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4241,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.460112 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f): perf score=1.000000
I20260812 06:17:41.583356 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.123s	user 0.091s	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":997,"lbm_read_time_us":8072,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24424,"lbm_writes_lt_1ms":443,"mutex_wait_us":252,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:41.584007 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=10.126437
I20260812 06:17:41.626251 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.042s	user 0.018s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17421,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:41.626793 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=2.188937
I20260812 06:17:41.641985 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.015s	user 0.003s	sys 0.012s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5665,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.642562 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f): perf score=1.000000
I20260812 06:17:41.768306 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.126s	user 0.089s	sys 0.036s 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":540,"lbm_read_time_us":9933,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24285,"lbm_writes_lt_1ms":443,"mutex_wait_us":125,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2000}
I20260812 06:17:41.768972 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=10.126437
I20260812 06:17:41.820775 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.052s	user 0.022s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19363,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:41.821389 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=2.188937
I20260812 06:17:41.832572 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4320,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.833141 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushMRSOp(b0622bdc099843449f11b5771172a65f): perf score=1.000000
I20260812 06:17:41.878485 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushMRSOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.045s	user 0.028s	sys 0.004s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":174,"dirs.run_wall_time_us":1209,"drs_written":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1837,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:41.879496 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling LogGCOp(b0622bdc099843449f11b5771172a65f): free 121006437 bytes of WAL
I20260812 06:17:41.879772 24279 log_reader.cc:385] T b0622bdc099843449f11b5771172a65f: removed 12 log segments from log reader
I20260812 06:17:41.879844 24279 log.cc:1079] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/b0622bdc099843449f11b5771172a65f/wal-000000003 (ops 12-16)
I20260812 06:17:41.879895 24279 log.cc:1079] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/b0622bdc099843449f11b5771172a65f/wal-000000004 (ops 17-21)
I20260812 06:17:41.879959 24279 log.cc:1079] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/b0622bdc099843449f11b5771172a65f/wal-000000005 (ops 22-26)
I20260812 06:17:41.880002 24279 log.cc:1079] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/b0622bdc099843449f11b5771172a65f/wal-000000006 (ops 27-31)
I20260812 06:17:41.880041 24279 log.cc:1079] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/b0622bdc099843449f11b5771172a65f/wal-000000007 (ops 32-36)
I20260812 06:17:41.880081 24279 log.cc:1079] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/b0622bdc099843449f11b5771172a65f/wal-000000008 (ops 37-40)
I20260812 06:17:41.880121 24279 log.cc:1079] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/b0622bdc099843449f11b5771172a65f/wal-000000009 (ops 41-45)
I20260812 06:17:41.880162 24279 log.cc:1079] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/b0622bdc099843449f11b5771172a65f/wal-000000010 (ops 46-50)
I20260812 06:17:41.880203 24279 log.cc:1079] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/b0622bdc099843449f11b5771172a65f/wal-000000011 (ops 51-55)
I20260812 06:17:41.880244 24279 log.cc:1079] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/b0622bdc099843449f11b5771172a65f/wal-000000012 (ops 56-60)
I20260812 06:17:41.880282 24279 log.cc:1079] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/b0622bdc099843449f11b5771172a65f/wal-000000013 (ops 61-65)
I20260812 06:17:41.880321 24279 log.cc:1079] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/b0622bdc099843449f11b5771172a65f/wal-000000014 (ops 66-70)
I20260812 06:17:41.908638 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: LogGCOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.029s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:41.909111 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling UndoDeltaBlockGCOp(b0622bdc099843449f11b5771172a65f): 482 bytes on disk
I20260812 06:17:41.909673 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: UndoDeltaBlockGCOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:17:41.910168 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=2.188937
I20260812 06:17:41.932668 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.022s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4827,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.933239 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=2.188937
I20260812 06:17:41.944732 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4442,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.945221 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f): perf score=1.000000
I20260812 06:17:42.159780 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.214s	user 0.140s	sys 0.072s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877339,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":907,"lbm_read_time_us":14988,"lbm_reads_lt_1ms":674,"lbm_write_time_us":37336,"lbm_writes_lt_1ms":643,"mutex_wait_us":175,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6784,"thread_start_us":97,"threads_started":1,"update_count":3000}
I20260812 06:17:42.160679 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=14.095187
I20260812 06:17:42.208467 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.048s	user 0.029s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21217,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:42.209158 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f): perf score=1.000000
I20260812 06:17:42.350654 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.141s	user 0.099s	sys 0.042s 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":150,"lbm_read_time_us":8879,"lbm_reads_lt_1ms":467,"lbm_write_time_us":25714,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":2000}
I20260812 06:17:42.351343 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=10.126437
I20260812 06:17:42.387703 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.036s	user 0.021s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13953,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:42.388430 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=2.188937
I20260812 06:17:42.399745 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4308,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.400353 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f): perf score=1.000000
I20260812 06:17:42.532153 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.132s	user 0.098s	sys 0.031s 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":590,"lbm_read_time_us":8898,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23652,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13440,"update_count":2000}
I20260812 06:17:42.532634 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=10.126437
I20260812 06:17:42.576529 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.044s	user 0.024s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16775,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:42.577041 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=2.188937
I20260812 06:17:42.588465 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4127,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.589241 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f): perf score=1.000000
I20260812 06:17:42.723474 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.134s	user 0.110s	sys 0.024s 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":243,"lbm_read_time_us":9927,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26515,"lbm_writes_lt_1ms":443,"mutex_wait_us":54,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2000}
I20260812 06:17:42.724197 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=10.126437
I20260812 06:17:42.764146 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.040s	user 0.021s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17520,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:42.764669 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=2.188937
I20260812 06:17:42.777258 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4536,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.777801 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f): perf score=1.000000
I20260812 06:17:42.909926 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.132s	user 0.107s	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":54,"lbm_read_time_us":8821,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26760,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2000}
I20260812 06:17:42.910830 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=10.126437
I20260812 06:17:42.955894 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.045s	user 0.022s	sys 0.021s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16455,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:42.956475 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=2.188937
I20260812 06:17:42.969445 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.013s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4337,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.970098 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f): perf score=1.000000
I20260812 06:17:43.126214 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.156s	user 0.107s	sys 0.048s 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":526,"lbm_read_time_us":10940,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26824,"lbm_writes_lt_1ms":443,"mutex_wait_us":274,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2000}
I20260812 06:17:43.126984 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=11.118625
I20260812 06:17:43.165686 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.038s	user 0.030s	sys 0.008s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":16314,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:43.166394 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=2.188937
I20260812 06:17:43.185057 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.018s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5918,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:43.185678 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f): perf score=1.000000
I20260812 06:17:43.321902 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.136s	user 0.112s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672270,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":129,"lbm_read_time_us":7291,"lbm_reads_lt_1ms":464,"lbm_write_time_us":28795,"lbm_writes_lt_1ms":443,"mutex_wait_us":93,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:43.322849 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=10.126437
I20260812 06:17:43.364779 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.042s	user 0.031s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18441,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:43.365413 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=2.188937
I20260812 06:17:43.384975 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.019s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6212,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:43.385470 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushMRSOp(b0622bdc099843449f11b5771172a65f): perf score=1.000000
I20260812 06:17:43.437851 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushMRSOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.052s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":277,"dirs.run_wall_time_us":1462,"drs_written":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1775,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31,"spinlock_wait_cycles":9472}
I20260812 06:17:43.438748 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling LogGCOp(b0622bdc099843449f11b5771172a65f): free 124257193 bytes of WAL
I20260812 06:17:43.439034 24279 log_reader.cc:385] T b0622bdc099843449f11b5771172a65f: removed 12 log segments from log reader
I20260812 06:17:43.439100 24279 log.cc:1079] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/b0622bdc099843449f11b5771172a65f/wal-000000015 (ops 71-75)
I20260812 06:17:43.439137 24279 log.cc:1079] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/b0622bdc099843449f11b5771172a65f/wal-000000016 (ops 76-80)
I20260812 06:17:43.439167 24279 log.cc:1079] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/b0622bdc099843449f11b5771172a65f/wal-000000017 (ops 81-85)
I20260812 06:17:43.439198 24279 log.cc:1079] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/b0622bdc099843449f11b5771172a65f/wal-000000018 (ops 86-90)
I20260812 06:17:43.439229 24279 log.cc:1079] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/b0622bdc099843449f11b5771172a65f/wal-000000019 (ops 91-95)
I20260812 06:17:43.439262 24279 log.cc:1079] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/b0622bdc099843449f11b5771172a65f/wal-000000020 (ops 96-100)
I20260812 06:17:43.439283 24279 log.cc:1079] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/b0622bdc099843449f11b5771172a65f/wal-000000021 (ops 101-104)
I20260812 06:17:43.439309 24279 log.cc:1079] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/b0622bdc099843449f11b5771172a65f/wal-000000022 (ops 105-109)
I20260812 06:17:43.439335 24279 log.cc:1079] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/b0622bdc099843449f11b5771172a65f/wal-000000023 (ops 110-114)
I20260812 06:17:43.439365 24279 log.cc:1079] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/b0622bdc099843449f11b5771172a65f/wal-000000024 (ops 115-119)
I20260812 06:17:43.439399 24279 log.cc:1079] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/b0622bdc099843449f11b5771172a65f/wal-000000025 (ops 120-124)
I20260812 06:17:43.439431 24279 log.cc:1079] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/b0622bdc099843449f11b5771172a65f/wal-000000026 (ops 125-129)
I20260812 06:17:43.470592 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: LogGCOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.032s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:17:43.471128 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling UndoDeltaBlockGCOp(b0622bdc099843449f11b5771172a65f): 483 bytes on disk
I20260812 06:17:43.471789 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: UndoDeltaBlockGCOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":89,"lbm_reads_lt_1ms":4}
I20260812 06:17:43.472384 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=6.157687
I20260812 06:17:43.495115 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.023s	user 0.011s	sys 0.009s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":8879,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:43.495647 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling LogGCOp(b0622bdc099843449f11b5771172a65f): free 12018006 bytes of WAL
I20260812 06:17:43.495872 24279 log_reader.cc:385] T b0622bdc099843449f11b5771172a65f: removed 1 log segments from log reader
I20260812 06:17:43.495918 24279 log.cc:1079] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/b0622bdc099843449f11b5771172a65f/wal-000000027 (ops 130-134)
I20260812 06:17:43.498234 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: LogGCOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.002s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:43.498617 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=2.188937
I20260812 06:17:43.511204 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.012s	user 0.001s	sys 0.010s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4493,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:43.511734 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f): perf score=1.000000
I20260812 06:17:43.708822 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.197s	user 0.170s	sys 0.024s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979752,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":647,"lbm_read_time_us":13084,"lbm_reads_lt_1ms":766,"lbm_write_time_us":40721,"lbm_writes_lt_1ms":743,"mutex_wait_us":18,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":9856,"thread_start_us":84,"threads_started":1,"update_count":3500}
I20260812 06:17:43.709694 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=14.095187
I20260812 06:17:43.759543 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.050s	user 0.034s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19166,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:43.760617 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=2.188937
I20260812 06:17:43.774444 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.014s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5147,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:43.775009 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f): perf score=1.000000
I20260812 06:17:43.976508 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.201s	user 0.133s	sys 0.056s 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":226,"lbm_read_time_us":11603,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33842,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14080,"update_count":2500}
I20260812 06:17:43.977309 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=14.095187
I20260812 06:17:44.036759 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.059s	user 0.027s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22629,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:44.037299 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=2.188937
I20260812 06:17:44.048939 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4194,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:44.049667 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f): perf score=1.000000
I20260812 06:17:44.218480 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.168s	user 0.136s	sys 0.021s 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":314,"lbm_read_time_us":10053,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33759,"lbm_writes_lt_1ms":543,"mutex_wait_us":58,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2500}
I20260812 06:17:44.219187 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=14.095187
I20260812 06:17:44.276458 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.057s	user 0.021s	sys 0.033s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":25069,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:44.277083 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=2.188937
I20260812 06:17:44.289350 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4623,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:44.289829 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f): perf score=1.000000
I20260812 06:17:44.452459 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.162s	user 0.119s	sys 0.033s 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":246,"lbm_read_time_us":10103,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33811,"lbm_writes_lt_1ms":543,"mutex_wait_us":76,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:44.453194 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=14.095187
I20260812 06:17:44.513981 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.061s	user 0.035s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25650,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:44.514772 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=2.188937
I20260812 06:17:44.534328 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.019s	user 0.019s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7378,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:44.534971 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f): perf score=1.000000
I20260812 06:17:44.692677 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.157s	user 0.115s	sys 0.036s 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":231,"lbm_read_time_us":10086,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32320,"lbm_writes_lt_1ms":543,"mutex_wait_us":62,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13952,"update_count":2500}
I20260812 06:17:44.693401 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=14.095187
I20260812 06:17:44.743157 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.050s	user 0.027s	sys 0.015s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19585,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:44.743709 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=2.188937
I20260812 06:17:44.756496 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.013s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4380,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:44.757136 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f): perf score=1.000000
I20260812 06:17:44.931784 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.174s	user 0.119s	sys 0.043s 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":804,"lbm_read_time_us":11388,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32314,"lbm_writes_lt_1ms":543,"mutex_wait_us":320,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":22400,"update_count":2500}
I20260812 06:17:44.932372 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=14.095187
I20260812 06:17:44.977560 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.045s	user 0.021s	sys 0.020s Metrics: {"bytes_written":16409897,"delete_count":0,"lbm_write_time_us":19599,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:44.978236 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushMRSOp(b0622bdc099843449f11b5771172a65f): perf score=1.000000
I20260812 06:17:45.007961 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushMRSOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.030s	user 0.024s	sys 0.003s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":52,"dirs.run_cpu_time_us":238,"dirs.run_wall_time_us":1549,"drs_written":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1744,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:45.008656 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling LogGCOp(b0622bdc099843449f11b5771172a65f): free 124710562 bytes of WAL
I20260812 06:17:45.008910 24279 log_reader.cc:385] T b0622bdc099843449f11b5771172a65f: removed 12 log segments from log reader
I20260812 06:17:45.008956 24279 log.cc:1079] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/b0622bdc099843449f11b5771172a65f/wal-000000028 (ops 135-139)
I20260812 06:17:45.008986 24279 log.cc:1079] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/b0622bdc099843449f11b5771172a65f/wal-000000029 (ops 140-144)
I20260812 06:17:45.009047 24279 log.cc:1079] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/b0622bdc099843449f11b5771172a65f/wal-000000030 (ops 145-149)
I20260812 06:17:45.009093 24279 log.cc:1079] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/b0622bdc099843449f11b5771172a65f/wal-000000031 (ops 150-154)
I20260812 06:17:45.009135 24279 log.cc:1079] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/b0622bdc099843449f11b5771172a65f/wal-000000032 (ops 155-159)
I20260812 06:17:45.009174 24279 log.cc:1079] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/b0622bdc099843449f11b5771172a65f/wal-000000033 (ops 160-164)
I20260812 06:17:45.009219 24279 log.cc:1079] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/b0622bdc099843449f11b5771172a65f/wal-000000034 (ops 165-169)
I20260812 06:17:45.009259 24279 log.cc:1079] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/b0622bdc099843449f11b5771172a65f/wal-000000035 (ops 170-174)
I20260812 06:17:45.009311 24279 log.cc:1079] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/b0622bdc099843449f11b5771172a65f/wal-000000036 (ops 175-179)
I20260812 06:17:45.009356 24279 log.cc:1079] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/b0622bdc099843449f11b5771172a65f/wal-000000037 (ops 180-184)
I20260812 06:17:45.009395 24279 log.cc:1079] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/b0622bdc099843449f11b5771172a65f/wal-000000038 (ops 185-189)
I20260812 06:17:45.009438 24279 log.cc:1079] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/b0622bdc099843449f11b5771172a65f/wal-000000039 (ops 190-194)
I20260812 06:17:45.037132 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: LogGCOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:17:45.037961 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=4.173312
I20260812 06:17:45.052505 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":5374417,"delete_count":0,"lbm_write_time_us":5875,"lbm_writes_lt_1ms":134,"reinsert_count":0,"update_count":655}
I20260812 06:17:45.052999 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling LogGCOp(b0622bdc099843449f11b5771172a65f): free 8767140 bytes of WAL
I20260812 06:17:45.053225 24279 log_reader.cc:385] T b0622bdc099843449f11b5771172a65f: removed 1 log segments from log reader
I20260812 06:17:45.053269 24279 log.cc:1079] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/b0622bdc099843449f11b5771172a65f/wal-000000040 (ops 195-199)
I20260812 06:17:45.055173 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: LogGCOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:45.055495 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f): perf score=1.196750
I20260812 06:17:45.064492 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: FlushDeltaMemStoresOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.009s	user 0.006s	sys 0.001s Metrics: {"bytes_written":2830880,"delete_count":0,"lbm_write_time_us":2878,"lbm_writes_lt_1ms":72,"reinsert_count":0,"update_count":345}
I20260812 06:17:45.065186 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling UndoDeltaBlockGCOp(b0622bdc099843449f11b5771172a65f): 492 bytes on disk
I20260812 06:17:45.065927 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: UndoDeltaBlockGCOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":132,"lbm_reads_lt_1ms":4}
I20260812 06:17:45.066637 24350 maintenance_manager.cc:419] P 6403323564314e57961bb66ea2659917: Scheduling MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f): perf score=1.000000
I20260812 06:17:45.091714 24170 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.935s	user 1.878s	sys 0.097s
I20260812 06:17:45.178942 24170 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.087s	user 0.001s	sys 0.004s
I20260812 06:17:45.179812 24170 tablet_server.cc:179] TabletServer@127.23.154.129:0 shutting down...
I20260812 06:17:45.236933 24279 maintenance_manager.cc:643] P 6403323564314e57961bb66ea2659917: MajorDeltaCompactionOp(b0622bdc099843449f11b5771172a65f) complete. Timing: real 0.170s	user 0.107s	sys 0.063s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877188,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1309,"lbm_read_time_us":13868,"lbm_reads_lt_1ms":669,"lbm_write_time_us":31904,"lbm_writes_lt_1ms":643,"mutex_wait_us":145,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4224,"thread_start_us":87,"threads_started":1,"update_count":3000}
I20260812 06:17:45.238148 24170 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:45.238588 24170 tablet_replica.cc:333] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917: stopping tablet replica
I20260812 06:17:45.238852 24170 raft_consensus.cc:2243] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:45.239111 24170 raft_consensus.cc:2272] T b0622bdc099843449f11b5771172a65f P 6403323564314e57961bb66ea2659917 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:45.264737 24170 tablet_server.cc:196] TabletServer@127.23.154.129:0 shutdown complete.
I20260812 06:17:45.288188 24170 master.cc:562] Master@127.23.154.190:44201 shutting down...
I20260812 06:17:45.291630 24170 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 96b29d88240143dca57e5741d6455f75 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:45.291847 24170 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 96b29d88240143dca57e5741d6455f75 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:45.291949 24170 tablet_replica.cc:333] T 00000000000000000000000000000000 P 96b29d88240143dca57e5741d6455f75: stopping tablet replica
I20260812 06:17:45.304683 24170 master.cc:584] Master@127.23.154.190:44201 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5583 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:45.389719 24170 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.23.154.190:35979
I20260812 06:17:45.390133 24170 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:45.392168 24391 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:45.392268 24389 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:45.392201 24170 server_base.cc:1061] running on GCE node
W20260812 06:17:45.392328 24388 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:45.392573 24170 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:45.392640 24170 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:45.392657 24170 hybrid_clock.cc:648] HybridClock initialized: now 1786515465392657 us; error 0 us; skew 500 ppm
I20260812 06:17:45.393479 24170 webserver.cc:533] Webserver started at http://127.23.154.190:46577/ using document root <none> and password file <none>
I20260812 06:17:45.393715 24170 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:45.393769 24170 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:45.393827 24170 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:45.394197 24170 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/master-0-root/instance:
uuid: "541f9bde4e4c4b36b952e4426dbb7305"
format_stamp: "Formatted at 2026-08-12 06:17:45 on dist-test-slave-njxd"
I20260812 06:17:45.395718 24170 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:17:45.396644 24397 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:45.396934 24170 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:45.397063 24170 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/master-0-root
uuid: "541f9bde4e4c4b36b952e4426dbb7305"
format_stamp: "Formatted at 2026-08-12 06:17:45 on dist-test-slave-njxd"
I20260812 06:17:45.397137 24170 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:45.422647 24170 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:45.423035 24170 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:45.427593 24170 rpc_server.cc:307] RPC server started. Bound to: 127.23.154.190:35979
I20260812 06:17:45.429122 24458 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.154.190:35979 every 8 connection(s)
I20260812 06:17:45.432526 24459 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:45.436968 24459 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 541f9bde4e4c4b36b952e4426dbb7305: Bootstrap starting.
I20260812 06:17:45.437891 24459 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 541f9bde4e4c4b36b952e4426dbb7305: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:45.439196 24459 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 541f9bde4e4c4b36b952e4426dbb7305: No bootstrap required, opened a new log
I20260812 06:17:45.439656 24459 raft_consensus.cc:359] T 00000000000000000000000000000000 P 541f9bde4e4c4b36b952e4426dbb7305 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "541f9bde4e4c4b36b952e4426dbb7305" member_type: VOTER }
I20260812 06:17:45.439747 24459 raft_consensus.cc:385] T 00000000000000000000000000000000 P 541f9bde4e4c4b36b952e4426dbb7305 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:45.439803 24459 raft_consensus.cc:740] T 00000000000000000000000000000000 P 541f9bde4e4c4b36b952e4426dbb7305 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 541f9bde4e4c4b36b952e4426dbb7305, State: Initialized, Role: FOLLOWER
I20260812 06:17:45.439998 24459 consensus_queue.cc:260] T 00000000000000000000000000000000 P 541f9bde4e4c4b36b952e4426dbb7305 [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: "541f9bde4e4c4b36b952e4426dbb7305" member_type: VOTER }
I20260812 06:17:45.440099 24459 raft_consensus.cc:399] T 00000000000000000000000000000000 P 541f9bde4e4c4b36b952e4426dbb7305 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:45.440166 24459 raft_consensus.cc:493] T 00000000000000000000000000000000 P 541f9bde4e4c4b36b952e4426dbb7305 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:45.440227 24459 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 541f9bde4e4c4b36b952e4426dbb7305 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:45.440976 24459 raft_consensus.cc:515] T 00000000000000000000000000000000 P 541f9bde4e4c4b36b952e4426dbb7305 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "541f9bde4e4c4b36b952e4426dbb7305" member_type: VOTER }
I20260812 06:17:45.441131 24459 leader_election.cc:304] T 00000000000000000000000000000000 P 541f9bde4e4c4b36b952e4426dbb7305 [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: 541f9bde4e4c4b36b952e4426dbb7305; no voters: 
I20260812 06:17:45.441365 24459 leader_election.cc:290] T 00000000000000000000000000000000 P 541f9bde4e4c4b36b952e4426dbb7305 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:45.441545 24462 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 541f9bde4e4c4b36b952e4426dbb7305 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:45.441807 24462 raft_consensus.cc:697] T 00000000000000000000000000000000 P 541f9bde4e4c4b36b952e4426dbb7305 [term 1 LEADER]: Becoming Leader. State: Replica: 541f9bde4e4c4b36b952e4426dbb7305, State: Running, Role: LEADER
I20260812 06:17:45.441946 24459 sys_catalog.cc:565] T 00000000000000000000000000000000 P 541f9bde4e4c4b36b952e4426dbb7305 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:45.441983 24462 consensus_queue.cc:237] T 00000000000000000000000000000000 P 541f9bde4e4c4b36b952e4426dbb7305 [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: "541f9bde4e4c4b36b952e4426dbb7305" member_type: VOTER }
I20260812 06:17:45.442443 24463 sys_catalog.cc:455] T 00000000000000000000000000000000 P 541f9bde4e4c4b36b952e4426dbb7305 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "541f9bde4e4c4b36b952e4426dbb7305" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "541f9bde4e4c4b36b952e4426dbb7305" member_type: VOTER } }
I20260812 06:17:45.442458 24464 sys_catalog.cc:455] T 00000000000000000000000000000000 P 541f9bde4e4c4b36b952e4426dbb7305 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 541f9bde4e4c4b36b952e4426dbb7305. Latest consensus state: current_term: 1 leader_uuid: "541f9bde4e4c4b36b952e4426dbb7305" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "541f9bde4e4c4b36b952e4426dbb7305" member_type: VOTER } }
I20260812 06:17:45.442597 24464 sys_catalog.cc:458] T 00000000000000000000000000000000 P 541f9bde4e4c4b36b952e4426dbb7305 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:45.442812 24463 sys_catalog.cc:458] T 00000000000000000000000000000000 P 541f9bde4e4c4b36b952e4426dbb7305 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:45.443270 24468 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:45.443979 24468 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:45.444173 24170 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:45.445987 24468 catalog_manager.cc:1383] Generated new cluster ID: e5670998c2534de6a479447efac880ed
I20260812 06:17:45.446038 24468 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:45.482002 24468 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:45.482605 24468 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:45.499215 24468 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 541f9bde4e4c4b36b952e4426dbb7305: Generated new TSK 0
I20260812 06:17:45.499423 24468 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:45.509073 24170 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:45.511072 24482 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:45.511086 24481 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:45.511183 24170 server_base.cc:1061] running on GCE node
W20260812 06:17:45.511198 24484 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:45.511591 24170 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:45.511637 24170 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:45.511687 24170 hybrid_clock.cc:648] HybridClock initialized: now 1786515465511687 us; error 0 us; skew 500 ppm
I20260812 06:17:45.512501 24170 webserver.cc:533] Webserver started at http://127.23.154.129:41961/ using document root <none> and password file <none>
I20260812 06:17:45.512670 24170 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:45.512738 24170 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:45.512806 24170 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:45.513161 24170 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root/instance:
uuid: "744558ca894541dcbfbb6d3ddedf929e"
format_stamp: "Formatted at 2026-08-12 06:17:45 on dist-test-slave-njxd"
I20260812 06:17:45.514720 24170 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:17:45.515662 24491 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:45.515973 24170 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:45.516057 24170 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root
uuid: "744558ca894541dcbfbb6d3ddedf929e"
format_stamp: "Formatted at 2026-08-12 06:17:45 on dist-test-slave-njxd"
I20260812 06:17:45.516145 24170 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:45.547492 24170 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:45.547935 24170 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:45.548295 24170 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:45.548820 24170 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:45.548858 24170 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:45.548892 24170 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:45.548944 24170 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:45.553297 24170 rpc_server.cc:307] RPC server started. Bound to: 127.23.154.129:35809
I20260812 06:17:45.554032 24563 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.154.129:35809 every 8 connection(s)
I20260812 06:17:45.562978 24564 heartbeater.cc:344] Connected to a master server at 127.23.154.190:35979
I20260812 06:17:45.563127 24564 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:45.563432 24564 heartbeater.cc:507] Master 127.23.154.190:35979 requested a full tablet report, sending...
I20260812 06:17:45.564198 24414 ts_manager.cc:194] Registered new tserver with Master: 744558ca894541dcbfbb6d3ddedf929e (127.23.154.129:35809)
I20260812 06:17:45.564985 24414 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:43944
I20260812 06:17:45.565007 24170 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011002844s
I20260812 06:17:45.572350 24414 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:43946:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:45.581633 24523 tablet_service.cc:1511] Processing CreateTablet for tablet 232b92a949de45bb93492c5b1b547f53 (DEFAULT_TABLE table=heavy-update-compaction-test [id=b6df05b06b704960995260efc4b9d9cf]), partition=
I20260812 06:17:45.581951 24523 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 232b92a949de45bb93492c5b1b547f53. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:45.584055 24579 tablet_bootstrap.cc:492] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Bootstrap starting.
I20260812 06:17:45.584945 24579 tablet_bootstrap.cc:654] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:45.586109 24579 tablet_bootstrap.cc:492] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: No bootstrap required, opened a new log
I20260812 06:17:45.586201 24579 ts_tablet_manager.cc:1403] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:45.586622 24579 raft_consensus.cc:359] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "744558ca894541dcbfbb6d3ddedf929e" member_type: VOTER last_known_addr { host: "127.23.154.129" port: 35809 } }
I20260812 06:17:45.586745 24579 raft_consensus.cc:385] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:45.586795 24579 raft_consensus.cc:740] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 744558ca894541dcbfbb6d3ddedf929e, State: Initialized, Role: FOLLOWER
I20260812 06:17:45.586937 24579 consensus_queue.cc:260] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e [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: "744558ca894541dcbfbb6d3ddedf929e" member_type: VOTER last_known_addr { host: "127.23.154.129" port: 35809 } }
I20260812 06:17:45.587055 24579 raft_consensus.cc:399] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:45.587101 24579 raft_consensus.cc:493] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:45.587154 24579 raft_consensus.cc:3060] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:45.587914 24579 raft_consensus.cc:515] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "744558ca894541dcbfbb6d3ddedf929e" member_type: VOTER last_known_addr { host: "127.23.154.129" port: 35809 } }
I20260812 06:17:45.588079 24579 leader_election.cc:304] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e [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: 744558ca894541dcbfbb6d3ddedf929e; no voters: 
I20260812 06:17:45.588316 24579 leader_election.cc:290] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:45.588455 24581 raft_consensus.cc:2804] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:45.588665 24579 ts_tablet_manager.cc:1434] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:17:45.588718 24564 heartbeater.cc:499] Master 127.23.154.190:35979 was elected leader, sending a full tablet report...
I20260812 06:17:45.588727 24581 raft_consensus.cc:697] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e [term 1 LEADER]: Becoming Leader. State: Replica: 744558ca894541dcbfbb6d3ddedf929e, State: Running, Role: LEADER
I20260812 06:17:45.588896 24581 consensus_queue.cc:237] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e [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: "744558ca894541dcbfbb6d3ddedf929e" member_type: VOTER last_known_addr { host: "127.23.154.129" port: 35809 } }
I20260812 06:17:45.590324 24414 catalog_manager.cc:5719] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e reported cstate change: term changed from 0 to 1, leader changed from <none> to 744558ca894541dcbfbb6d3ddedf929e (127.23.154.129). New cstate: current_term: 1 leader_uuid: "744558ca894541dcbfbb6d3ddedf929e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "744558ca894541dcbfbb6d3ddedf929e" member_type: VOTER last_known_addr { host: "127.23.154.129" port: 35809 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:45.650838 24170 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.016s	sys 0.006s
I20260812 06:17:45.804812 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushMRSOp(232b92a949de45bb93492c5b1b547f53): perf score=19.054940
I20260812 06:17:45.960877 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushMRSOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.156s	user 0.097s	sys 0.055s Metrics: {"bytes_written":12389540,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":86,"dirs.run_cpu_time_us":250,"dirs.run_wall_time_us":925,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40604,"lbm_writes_lt_1ms":759,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1510}
I20260812 06:17:45.961652 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling LogGCOp(232b92a949de45bb93492c5b1b547f53): free 20743880 bytes of WAL
I20260812 06:17:45.961896 24497 log_reader.cc:385] T 232b92a949de45bb93492c5b1b547f53: removed 2 log segments from log reader
I20260812 06:17:45.961941 24497 log.cc:1079] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/232b92a949de45bb93492c5b1b547f53/wal-000000001 (ops 1-6)
I20260812 06:17:45.961973 24497 log.cc:1079] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/232b92a949de45bb93492c5b1b547f53/wal-000000002 (ops 7-11)
I20260812 06:17:45.966707 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: LogGCOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.005s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:17:45.967294 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=2.188937
I20260812 06:17:45.984992 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.017s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4020609,"delete_count":0,"lbm_write_time_us":6487,"lbm_writes_lt_1ms":101,"reinsert_count":0,"update_count":490}
I20260812 06:17:45.985733 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling UndoDeltaBlockGCOp(232b92a949de45bb93492c5b1b547f53): 16411396 bytes on disk
I20260812 06:17:45.986370 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: UndoDeltaBlockGCOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":100,"lbm_reads_lt_1ms":4}
I20260812 06:17:45.986893 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling MajorDeltaCompactionOp(232b92a949de45bb93492c5b1b547f53): perf score=1.000000
I20260812 06:17:46.158298 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: MajorDeltaCompactionOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.171s	user 0.117s	sys 0.046s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":632,"lbm_read_time_us":11075,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26366,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2944,"thread_start_us":356,"threads_started":5,"update_count":2000}
I20260812 06:17:46.159045 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=14.095187
I20260812 06:17:46.204046 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.045s	user 0.021s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18908,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:46.204546 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling MajorDeltaCompactionOp(232b92a949de45bb93492c5b1b547f53): perf score=1.000000
I20260812 06:17:46.366736 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: MajorDeltaCompactionOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.162s	user 0.106s	sys 0.055s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1257,"lbm_read_time_us":13147,"lbm_reads_lt_1ms":467,"lbm_write_time_us":29125,"lbm_writes_lt_1ms":443,"mutex_wait_us":393,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":2000}
I20260812 06:17:46.367228 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=10.126437
I20260812 06:17:46.402601 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.035s	user 0.030s	sys 0.004s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15579,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:46.403303 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=2.188937
I20260812 06:17:46.416517 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.013s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4613,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:46.417100 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling MajorDeltaCompactionOp(232b92a949de45bb93492c5b1b547f53): perf score=1.000000
I20260812 06:17:46.552187 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: MajorDeltaCompactionOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.135s	user 0.093s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1010,"lbm_read_time_us":9677,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26745,"lbm_writes_lt_1ms":443,"mutex_wait_us":68,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:17:46.552871 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=10.126437
I20260812 06:17:46.602326 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.049s	user 0.031s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17438,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:46.602831 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=2.188937
I20260812 06:17:46.618736 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5929,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:46.619385 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling MajorDeltaCompactionOp(232b92a949de45bb93492c5b1b547f53): perf score=1.000000
I20260812 06:17:46.763397 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: MajorDeltaCompactionOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.144s	user 0.103s	sys 0.040s 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":722,"lbm_read_time_us":9276,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27694,"lbm_writes_lt_1ms":443,"mutex_wait_us":1,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2000}
I20260812 06:17:46.764122 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=10.126437
I20260812 06:17:46.807793 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.044s	user 0.025s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18711,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:46.808449 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=2.188937
I20260812 06:17:46.825887 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.017s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6748,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:46.826391 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling MajorDeltaCompactionOp(232b92a949de45bb93492c5b1b547f53): perf score=1.000000
I20260812 06:17:46.954308 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: MajorDeltaCompactionOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.128s	user 0.080s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":427,"dirs.run_cpu_time_us":1264,"dirs.run_wall_time_us":6358,"lbm_read_time_us":9727,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23142,"lbm_writes_lt_1ms":443,"mutex_wait_us":69,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":38272,"update_count":2000}
I20260812 06:17:46.955077 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=10.126437
I20260812 06:17:47.006942 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.052s	user 0.024s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17517,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:47.007571 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=2.188937
I20260812 06:17:47.020222 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4916,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.020700 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling MajorDeltaCompactionOp(232b92a949de45bb93492c5b1b547f53): perf score=1.000000
I20260812 06:17:47.177424 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: MajorDeltaCompactionOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.157s	user 0.108s	sys 0.048s 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":836,"lbm_read_time_us":10810,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25755,"lbm_writes_lt_1ms":443,"mutex_wait_us":42,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:47.178027 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=10.126437
I20260812 06:17:47.220222 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.042s	user 0.031s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16005,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:47.220710 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=2.188937
I20260812 06:17:47.232658 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4292,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.233470 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushMRSOp(232b92a949de45bb93492c5b1b547f53): perf score=1.000000
I20260812 06:17:47.261081 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushMRSOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.027s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":95,"dirs.run_cpu_time_us":345,"dirs.run_wall_time_us":1348,"drs_written":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1504,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:47.261759 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling LogGCOp(232b92a949de45bb93492c5b1b547f53): free 115943182 bytes of WAL
I20260812 06:17:47.261978 24497 log_reader.cc:385] T 232b92a949de45bb93492c5b1b547f53: removed 11 log segments from log reader
I20260812 06:17:47.262036 24497 log.cc:1079] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/232b92a949de45bb93492c5b1b547f53/wal-000000003 (ops 12-16)
I20260812 06:17:47.262089 24497 log.cc:1079] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/232b92a949de45bb93492c5b1b547f53/wal-000000004 (ops 17-21)
I20260812 06:17:47.262148 24497 log.cc:1079] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/232b92a949de45bb93492c5b1b547f53/wal-000000005 (ops 22-26)
I20260812 06:17:47.262192 24497 log.cc:1079] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/232b92a949de45bb93492c5b1b547f53/wal-000000006 (ops 27-31)
I20260812 06:17:47.262228 24497 log.cc:1079] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/232b92a949de45bb93492c5b1b547f53/wal-000000007 (ops 32-36)
I20260812 06:17:47.262265 24497 log.cc:1079] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/232b92a949de45bb93492c5b1b547f53/wal-000000008 (ops 37-41)
I20260812 06:17:47.262303 24497 log.cc:1079] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/232b92a949de45bb93492c5b1b547f53/wal-000000009 (ops 42-46)
I20260812 06:17:47.262339 24497 log.cc:1079] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/232b92a949de45bb93492c5b1b547f53/wal-000000010 (ops 47-51)
I20260812 06:17:47.262380 24497 log.cc:1079] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/232b92a949de45bb93492c5b1b547f53/wal-000000011 (ops 52-56)
I20260812 06:17:47.262418 24497 log.cc:1079] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/232b92a949de45bb93492c5b1b547f53/wal-000000012 (ops 57-61)
I20260812 06:17:47.262456 24497 log.cc:1079] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/232b92a949de45bb93492c5b1b547f53/wal-000000013 (ops 62-66)
I20260812 06:17:47.286888 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: LogGCOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.025s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:17:47.287526 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling UndoDeltaBlockGCOp(232b92a949de45bb93492c5b1b547f53): 447 bytes on disk
I20260812 06:17:47.288097 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: UndoDeltaBlockGCOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:17:47.288777 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=3.181125
I20260812 06:17:47.309363 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.020s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4348808,"delete_count":0,"lbm_write_time_us":6830,"lbm_writes_lt_1ms":109,"reinsert_count":0,"update_count":530}
I20260812 06:17:47.309834 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=2.188937
I20260812 06:17:47.330168 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.020s	user 0.001s	sys 0.018s Metrics: {"bytes_written":3856509,"delete_count":0,"lbm_write_time_us":4385,"lbm_writes_lt_1ms":97,"reinsert_count":0,"update_count":470}
I20260812 06:17:47.330722 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling MajorDeltaCompactionOp(232b92a949de45bb93492c5b1b547f53): perf score=1.000000
I20260812 06:17:47.538458 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: MajorDeltaCompactionOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.208s	user 0.114s	sys 0.092s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877338,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2103,"lbm_read_time_us":15042,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32942,"lbm_writes_lt_1ms":643,"mutex_wait_us":567,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6016,"thread_start_us":96,"threads_started":1,"update_count":3000}
I20260812 06:17:47.539373 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=14.095187
I20260812 06:17:47.605803 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.066s	user 0.034s	sys 0.031s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23581,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:47.606412 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=2.188937
I20260812 06:17:47.624092 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.017s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4409,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.624703 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling MajorDeltaCompactionOp(232b92a949de45bb93492c5b1b547f53): perf score=1.000000
I20260812 06:17:47.825758 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: MajorDeltaCompactionOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.201s	user 0.142s	sys 0.058s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":716,"lbm_read_time_us":11473,"lbm_reads_lt_1ms":564,"lbm_write_time_us":34111,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:17:47.826321 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=14.095187
I20260812 06:17:47.877255 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.051s	user 0.018s	sys 0.029s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21741,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:47.878036 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=2.188937
I20260812 06:17:47.905691 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.027s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4348807,"delete_count":0,"lbm_write_time_us":4942,"lbm_writes_lt_1ms":109,"reinsert_count":0,"update_count":530}
I20260812 06:17:47.906526 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=2.188937
I20260812 06:17:47.922708 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.016s	user 0.009s	sys 0.006s Metrics: {"bytes_written":3856509,"delete_count":0,"lbm_write_time_us":5929,"lbm_writes_lt_1ms":97,"reinsert_count":0,"update_count":470}
I20260812 06:17:47.923219 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling MajorDeltaCompactionOp(232b92a949de45bb93492c5b1b547f53): perf score=1.000000
I20260812 06:17:48.136200 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: MajorDeltaCompactionOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.213s	user 0.151s	sys 0.061s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877218,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":287,"lbm_read_time_us":13498,"lbm_reads_lt_1ms":673,"lbm_write_time_us":37458,"lbm_writes_lt_1ms":643,"mutex_wait_us":33,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":3000}
I20260812 06:17:48.137043 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=15.087375
I20260812 06:17:48.197019 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.060s	user 0.025s	sys 0.030s Metrics: {"bytes_written":16820145,"delete_count":0,"lbm_write_time_us":21960,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:48.197691 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=4.173312
I20260812 06:17:48.217022 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.019s	user 0.012s	sys 0.004s Metrics: {"bytes_written":6194893,"delete_count":0,"lbm_write_time_us":7834,"lbm_writes_lt_1ms":154,"reinsert_count":0,"update_count":755}
I20260812 06:17:48.217665 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=1.000000
I20260812 06:17:48.226958 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.009s	user 0.007s	sys 0.001s Metrics: {"bytes_written":1600127,"delete_count":0,"lbm_write_time_us":2557,"lbm_writes_lt_1ms":42,"reinsert_count":0,"update_count":195}
I20260812 06:17:48.228307 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling MajorDeltaCompactionOp(232b92a949de45bb93492c5b1b547f53): perf score=1.000000
I20260812 06:17:48.445559 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: MajorDeltaCompactionOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.217s	user 0.133s	sys 0.079s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877160,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":382,"lbm_read_time_us":14831,"lbm_reads_lt_1ms":673,"lbm_write_time_us":36291,"lbm_writes_lt_1ms":643,"mutex_wait_us":21,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":27904,"update_count":3000}
I20260812 06:17:48.446588 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=16.079562
I20260812 06:17:48.512842 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.066s	user 0.032s	sys 0.020s Metrics: {"bytes_written":17640630,"delete_count":0,"lbm_write_time_us":26134,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":431,"reinsert_count":0,"update_count":2150}
I20260812 06:17:48.513518 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=5.165500
I20260812 06:17:48.539487 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.026s	user 0.015s	sys 0.009s Metrics: {"bytes_written":6974360,"delete_count":0,"lbm_write_time_us":10782,"lbm_writes_lt_1ms":173,"reinsert_count":0,"update_count":850}
I20260812 06:17:48.540247 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling MajorDeltaCompactionOp(232b92a949de45bb93492c5b1b547f53): perf score=1.000000
I20260812 06:17:48.760972 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: MajorDeltaCompactionOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.220s	user 0.136s	sys 0.072s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877112,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":444,"lbm_read_time_us":14443,"lbm_reads_lt_1ms":664,"lbm_write_time_us":32919,"lbm_writes_lt_1ms":643,"mutex_wait_us":23,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":18176,"update_count":3000}
I20260812 06:17:48.761667 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=18.063937
I20260812 06:17:48.844403 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.083s	user 0.038s	sys 0.028s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":31480,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:48.845014 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=2.188937
I20260812 06:17:48.857208 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4123,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:48.857803 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushMRSOp(232b92a949de45bb93492c5b1b547f53): perf score=1.000000
I20260812 06:17:48.886796 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushMRSOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.029s	user 0.027s	sys 0.001s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":169,"dirs.run_wall_time_us":1288,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1835,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:48.887570 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling LogGCOp(232b92a949de45bb93492c5b1b547f53): free 129320532 bytes of WAL
I20260812 06:17:48.888108 24497 log_reader.cc:385] T 232b92a949de45bb93492c5b1b547f53: removed 13 log segments from log reader
I20260812 06:17:48.888185 24497 log.cc:1079] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/232b92a949de45bb93492c5b1b547f53/wal-000000014 (ops 67-71)
I20260812 06:17:48.888226 24497 log.cc:1079] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/232b92a949de45bb93492c5b1b547f53/wal-000000015 (ops 72-76)
I20260812 06:17:48.888249 24497 log.cc:1079] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/232b92a949de45bb93492c5b1b547f53/wal-000000016 (ops 77-80)
I20260812 06:17:48.888271 24497 log.cc:1079] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/232b92a949de45bb93492c5b1b547f53/wal-000000017 (ops 81-85)
I20260812 06:17:48.888296 24497 log.cc:1079] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/232b92a949de45bb93492c5b1b547f53/wal-000000018 (ops 86-90)
I20260812 06:17:48.888331 24497 log.cc:1079] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/232b92a949de45bb93492c5b1b547f53/wal-000000019 (ops 91-95)
I20260812 06:17:48.888355 24497 log.cc:1079] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/232b92a949de45bb93492c5b1b547f53/wal-000000020 (ops 96-100)
I20260812 06:17:48.888377 24497 log.cc:1079] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/232b92a949de45bb93492c5b1b547f53/wal-000000021 (ops 101-105)
I20260812 06:17:48.888403 24497 log.cc:1079] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/232b92a949de45bb93492c5b1b547f53/wal-000000022 (ops 106-110)
I20260812 06:17:48.888432 24497 log.cc:1079] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/232b92a949de45bb93492c5b1b547f53/wal-000000023 (ops 111-114)
I20260812 06:17:48.888463 24497 log.cc:1079] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/232b92a949de45bb93492c5b1b547f53/wal-000000024 (ops 115-119)
I20260812 06:17:48.888497 24497 log.cc:1079] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/232b92a949de45bb93492c5b1b547f53/wal-000000025 (ops 120-124)
I20260812 06:17:48.888530 24497 log.cc:1079] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/232b92a949de45bb93492c5b1b547f53/wal-000000026 (ops 125-129)
I20260812 06:17:48.921906 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: LogGCOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.034s	user 0.000s	sys 0.034s Metrics: {}
I20260812 06:17:48.922405 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=2.188937
I20260812 06:17:48.940641 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.018s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4377,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:48.941118 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=2.188937
I20260812 06:17:48.952425 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4342,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:48.953051 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling UndoDeltaBlockGCOp(232b92a949de45bb93492c5b1b547f53): 483 bytes on disk
I20260812 06:17:48.953822 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: UndoDeltaBlockGCOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":117,"lbm_reads_lt_1ms":4}
I20260812 06:17:48.954677 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling MajorDeltaCompactionOp(232b92a949de45bb93492c5b1b547f53): perf score=1.000000
I20260812 06:17:49.207302 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: MajorDeltaCompactionOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.252s	user 0.148s	sys 0.103s Metrics: {"cfile_cache_miss":834,"cfile_cache_miss_bytes":37082163,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1037,"lbm_read_time_us":17707,"lbm_reads_lt_1ms":874,"lbm_write_time_us":47728,"lbm_writes_lt_1ms":843,"mutex_wait_us":28,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":3200,"thread_start_us":88,"threads_started":1,"update_count":4000}
I20260812 06:17:49.208534 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=18.063937
I20260812 06:17:49.271939 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.063s	user 0.054s	sys 0.007s Metrics: {"bytes_written":20512314,"delete_count":0,"lbm_write_time_us":28398,"lbm_writes_lt_1ms":503,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2500}
I20260812 06:17:49.272466 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=2.188937
I20260812 06:17:49.298911 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.026s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5570,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:49.299384 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=2.188937
I20260812 06:17:49.310237 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4276,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:49.310835 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling MajorDeltaCompactionOp(232b92a949de45bb93492c5b1b547f53): perf score=1.000000
I20260812 06:17:49.589830 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: MajorDeltaCompactionOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.279s	user 0.205s	sys 0.063s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979630,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":612,"lbm_read_time_us":13989,"lbm_reads_lt_1ms":773,"lbm_write_time_us":64958,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":742,"mutex_wait_us":309,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":29568,"update_count":3500}
I20260812 06:17:49.590818 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=22.032687
I20260812 06:17:49.668087 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.077s	user 0.046s	sys 0.028s Metrics: {"bytes_written":24614711,"delete_count":0,"lbm_write_time_us":35433,"lbm_writes_lt_1ms":603,"reinsert_count":0,"update_count":3000}
I20260812 06:17:49.668708 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=2.188937
I20260812 06:17:49.690492 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.022s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6565,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:49.690984 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling MajorDeltaCompactionOp(232b92a949de45bb93492c5b1b547f53): perf score=1.000000
I20260812 06:17:49.906152 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: MajorDeltaCompactionOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.215s	user 0.165s	sys 0.041s Metrics: {"cfile_cache_miss":732,"cfile_cache_miss_bytes":32979498,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":3322,"lbm_read_time_us":14412,"lbm_reads_lt_1ms":764,"lbm_write_time_us":40701,"lbm_writes_lt_1ms":743,"mutex_wait_us":383,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":19712,"update_count":3500}
I20260812 06:17:49.906983 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=14.095187
I20260812 06:17:49.969020 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.062s	user 0.022s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21705,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:49.969645 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=2.188937
I20260812 06:17:49.981808 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4415,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:49.982288 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling MajorDeltaCompactionOp(232b92a949de45bb93492c5b1b547f53): perf score=1.000000
I20260812 06:17:50.138338 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: MajorDeltaCompactionOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.156s	user 0.096s	sys 0.055s 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":154,"lbm_read_time_us":11493,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28899,"lbm_writes_lt_1ms":543,"mutex_wait_us":55,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":25856,"update_count":2500}
I20260812 06:17:50.139209 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=12.110812
I20260812 06:17:50.171897 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.032s	user 0.010s	sys 0.020s Metrics: {"bytes_written":13620266,"delete_count":0,"lbm_write_time_us":14579,"lbm_writes_lt_1ms":335,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":1660}
I20260812 06:17:50.172452 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=1.196750
I20260812 06:17:50.190842 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.018s	user 0.009s	sys 0.004s Metrics: {"bytes_written":2789855,"delete_count":0,"lbm_write_time_us":4959,"lbm_writes_lt_1ms":71,"reinsert_count":0,"update_count":340}
I20260812 06:17:50.191437 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling MajorDeltaCompactionOp(232b92a949de45bb93492c5b1b547f53): perf score=1.000000
I20260812 06:17:50.355620 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: MajorDeltaCompactionOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.164s	user 0.101s	sys 0.054s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672249,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1049,"lbm_read_time_us":10461,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24368,"lbm_writes_lt_1ms":443,"mutex_wait_us":493,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":2000}
I20260812 06:17:50.356287 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=14.095187
I20260812 06:17:50.407114 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.051s	user 0.030s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19869,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:50.407662 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=2.188937
I20260812 06:17:50.430006 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.022s	user 0.006s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4228,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:50.430653 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushMRSOp(232b92a949de45bb93492c5b1b547f53): perf score=1.000000
I20260812 06:17:50.465277 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushMRSOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.034s	user 0.028s	sys 0.004s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":145,"dirs.run_wall_time_us":1303,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1561,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:50.466078 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling LogGCOp(232b92a949de45bb93492c5b1b547f53): free 124257515 bytes of WAL
I20260812 06:17:50.466370 24497 log_reader.cc:385] T 232b92a949de45bb93492c5b1b547f53: removed 12 log segments from log reader
I20260812 06:17:50.466416 24497 log.cc:1079] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/232b92a949de45bb93492c5b1b547f53/wal-000000027 (ops 130-134)
I20260812 06:17:50.466446 24497 log.cc:1079] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/232b92a949de45bb93492c5b1b547f53/wal-000000028 (ops 135-139)
I20260812 06:17:50.466502 24497 log.cc:1079] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/232b92a949de45bb93492c5b1b547f53/wal-000000029 (ops 140-144)
I20260812 06:17:50.466547 24497 log.cc:1079] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/232b92a949de45bb93492c5b1b547f53/wal-000000030 (ops 145-149)
I20260812 06:17:50.466594 24497 log.cc:1079] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/232b92a949de45bb93492c5b1b547f53/wal-000000031 (ops 150-154)
I20260812 06:17:50.466655 24497 log.cc:1079] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/232b92a949de45bb93492c5b1b547f53/wal-000000032 (ops 155-159)
I20260812 06:17:50.466699 24497 log.cc:1079] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/232b92a949de45bb93492c5b1b547f53/wal-000000033 (ops 160-164)
I20260812 06:17:50.466761 24497 log.cc:1079] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/232b92a949de45bb93492c5b1b547f53/wal-000000034 (ops 165-169)
I20260812 06:17:50.466797 24497 log.cc:1079] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/232b92a949de45bb93492c5b1b547f53/wal-000000035 (ops 170-174)
I20260812 06:17:50.466944 24497 log.cc:1079] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/232b92a949de45bb93492c5b1b547f53/wal-000000036 (ops 175-178)
I20260812 06:17:50.466988 24497 log.cc:1079] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/232b92a949de45bb93492c5b1b547f53/wal-000000037 (ops 179-183)
I20260812 06:17:50.467053 24497 log.cc:1079] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: Deleting log segment in path: /tmp/dist-test-taskTgKX4Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515459795371-24170-0/minicluster-data/ts-0-root/wals/232b92a949de45bb93492c5b1b547f53/wal-000000038 (ops 184-188)
I20260812 06:17:50.494453 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: LogGCOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.028s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:17:50.494952 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=2.188937
I20260812 06:17:50.511461 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.016s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4699,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:50.512015 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=2.188937
I20260812 06:17:50.527894 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6173,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:50.528600 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling MajorDeltaCompactionOp(232b92a949de45bb93492c5b1b547f53): perf score=1.000000
I20260812 06:17:50.765942 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: MajorDeltaCompactionOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.237s	user 0.170s	sys 0.067s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979750,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":564,"lbm_read_time_us":15924,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40982,"lbm_writes_lt_1ms":743,"mutex_wait_us":32,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":73472,"thread_start_us":89,"threads_started":1,"update_count":3500}
I20260812 06:17:50.766827 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling UndoDeltaBlockGCOp(232b92a949de45bb93492c5b1b547f53): 472 bytes on disk
I20260812 06:17:50.767488 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: UndoDeltaBlockGCOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":99,"lbm_reads_lt_1ms":4}
I20260812 06:17:50.768414 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=14.095187
I20260812 06:17:50.804358 24170 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.153s	user 1.903s	sys 0.208s
I20260812 06:17:50.815097 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.046s	user 0.030s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22502,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:50.815616 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53): perf score=2.188937
I20260812 06:17:50.825938 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: FlushDeltaMemStoresOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.010s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4253,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:50.826390 24565 maintenance_manager.cc:419] P 744558ca894541dcbfbb6d3ddedf929e: Scheduling MajorDeltaCompactionOp(232b92a949de45bb93492c5b1b547f53): perf score=1.000000
I20260812 06:17:50.847611 24170 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.043s	user 0.001s	sys 0.000s
I20260812 06:17:50.848203 24170 tablet_server.cc:179] TabletServer@127.23.154.129:0 shutting down...
I20260812 06:17:50.970983 24497 maintenance_manager.cc:643] P 744558ca894541dcbfbb6d3ddedf929e: MajorDeltaCompactionOp(232b92a949de45bb93492c5b1b547f53) complete. Timing: real 0.144s	user 0.102s	sys 0.042s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4262390,"cfile_cache_miss":502,"cfile_cache_miss_bytes":20512298,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":450,"lbm_read_time_us":8502,"lbm_reads_lt_1ms":518,"lbm_write_time_us":24800,"lbm_writes_lt_1ms":543,"mutex_wait_us":119,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":2500}
I20260812 06:17:50.971820 24170 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:50.972102 24170 tablet_replica.cc:333] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e: stopping tablet replica
I20260812 06:17:50.972299 24170 raft_consensus.cc:2243] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:50.972504 24170 raft_consensus.cc:2272] T 232b92a949de45bb93492c5b1b547f53 P 744558ca894541dcbfbb6d3ddedf929e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:50.977062 24170 tablet_server.cc:196] TabletServer@127.23.154.129:0 shutdown complete.
I20260812 06:17:51.019371 24170 master.cc:562] Master@127.23.154.190:35979 shutting down...
I20260812 06:17:51.023288 24170 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 541f9bde4e4c4b36b952e4426dbb7305 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:51.023502 24170 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 541f9bde4e4c4b36b952e4426dbb7305 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:51.023576 24170 tablet_replica.cc:333] T 00000000000000000000000000000000 P 541f9bde4e4c4b36b952e4426dbb7305: stopping tablet replica
I20260812 06:17:51.037240 24170 master.cc:584] Master@127.23.154.190:35979 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5739 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11323 ms total)

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