[==========] 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:18:13.401175  1422 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.1.99.190:43113
I20260812 06:18:13.402246  1422 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:18:13.402977  1422 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:13.409930  1430 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:18:13.409930  1433 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:18:13.410053  1422 server_base.cc:1061] running on GCE node
W20260812 06:18:13.410300  1431 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:18:13.410900  1422 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:13.411020  1422 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:18:13.411067  1422 hybrid_clock.cc:648] HybridClock initialized: now 1786515493411063 us; error 0 us; skew 500 ppm
I20260812 06:18:13.412878  1422 webserver.cc:533] Webserver started at http://127.1.99.190:43927/ using document root <none> and password file <none>
I20260812 06:18:13.413447  1422 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:13.413532  1422 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:13.413775  1422 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:13.415519  1422 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/master-0-root/instance:
uuid: "277b10ab22cd41afb3fee1089520fe6e"
format_stamp: "Formatted at 2026-08-12 06:18:13 on dist-test-slave-3kk6"
I20260812 06:18:13.419071  1422 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:18:13.421211  1443 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:18:13.422220  1422 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:13.422349  1422 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/master-0-root
uuid: "277b10ab22cd41afb3fee1089520fe6e"
format_stamp: "Formatted at 2026-08-12 06:18:13 on dist-test-slave-3kk6"
I20260812 06:18:13.422453  1422 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-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:18:13.436825  1422 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:13.437467  1422 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:18:13.437654  1422 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:13.445937  1422 rpc_server.cc:307] RPC server started. Bound to: 127.1.99.190:43113
I20260812 06:18:13.445957  1523 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.1.99.190:43113 every 8 connection(s)
I20260812 06:18:13.448359  1527 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:18:13.453965  1527 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 277b10ab22cd41afb3fee1089520fe6e: Bootstrap starting.
I20260812 06:18:13.456401  1527 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 277b10ab22cd41afb3fee1089520fe6e: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:13.457304  1527 log.cc:826] T 00000000000000000000000000000000 P 277b10ab22cd41afb3fee1089520fe6e: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:13.459069  1527 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 277b10ab22cd41afb3fee1089520fe6e: No bootstrap required, opened a new log
I20260812 06:18:13.461830  1527 raft_consensus.cc:359] T 00000000000000000000000000000000 P 277b10ab22cd41afb3fee1089520fe6e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "277b10ab22cd41afb3fee1089520fe6e" member_type: VOTER }
I20260812 06:18:13.461999  1527 raft_consensus.cc:385] T 00000000000000000000000000000000 P 277b10ab22cd41afb3fee1089520fe6e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:13.462100  1527 raft_consensus.cc:740] T 00000000000000000000000000000000 P 277b10ab22cd41afb3fee1089520fe6e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 277b10ab22cd41afb3fee1089520fe6e, State: Initialized, Role: FOLLOWER
I20260812 06:18:13.462797  1527 consensus_queue.cc:260] T 00000000000000000000000000000000 P 277b10ab22cd41afb3fee1089520fe6e [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: "277b10ab22cd41afb3fee1089520fe6e" member_type: VOTER }
I20260812 06:18:13.462971  1527 raft_consensus.cc:399] T 00000000000000000000000000000000 P 277b10ab22cd41afb3fee1089520fe6e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:13.463059  1527 raft_consensus.cc:493] T 00000000000000000000000000000000 P 277b10ab22cd41afb3fee1089520fe6e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:13.463217  1527 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 277b10ab22cd41afb3fee1089520fe6e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:13.464046  1527 raft_consensus.cc:515] T 00000000000000000000000000000000 P 277b10ab22cd41afb3fee1089520fe6e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "277b10ab22cd41afb3fee1089520fe6e" member_type: VOTER }
I20260812 06:18:13.464502  1527 leader_election.cc:304] T 00000000000000000000000000000000 P 277b10ab22cd41afb3fee1089520fe6e [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: 277b10ab22cd41afb3fee1089520fe6e; no voters: 
I20260812 06:18:13.464834  1527 leader_election.cc:290] T 00000000000000000000000000000000 P 277b10ab22cd41afb3fee1089520fe6e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:13.464977  1530 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 277b10ab22cd41afb3fee1089520fe6e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:13.465241  1530 raft_consensus.cc:697] T 00000000000000000000000000000000 P 277b10ab22cd41afb3fee1089520fe6e [term 1 LEADER]: Becoming Leader. State: Replica: 277b10ab22cd41afb3fee1089520fe6e, State: Running, Role: LEADER
I20260812 06:18:13.465668  1530 consensus_queue.cc:237] T 00000000000000000000000000000000 P 277b10ab22cd41afb3fee1089520fe6e [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: "277b10ab22cd41afb3fee1089520fe6e" member_type: VOTER }
I20260812 06:18:13.465895  1527 sys_catalog.cc:565] T 00000000000000000000000000000000 P 277b10ab22cd41afb3fee1089520fe6e [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:13.467672  1533 sys_catalog.cc:455] T 00000000000000000000000000000000 P 277b10ab22cd41afb3fee1089520fe6e [sys.catalog]: SysCatalogTable state changed. Reason: New leader 277b10ab22cd41afb3fee1089520fe6e. Latest consensus state: current_term: 1 leader_uuid: "277b10ab22cd41afb3fee1089520fe6e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "277b10ab22cd41afb3fee1089520fe6e" member_type: VOTER } }
I20260812 06:18:13.467703  1531 sys_catalog.cc:455] T 00000000000000000000000000000000 P 277b10ab22cd41afb3fee1089520fe6e [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "277b10ab22cd41afb3fee1089520fe6e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "277b10ab22cd41afb3fee1089520fe6e" member_type: VOTER } }
I20260812 06:18:13.467833  1531 sys_catalog.cc:458] T 00000000000000000000000000000000 P 277b10ab22cd41afb3fee1089520fe6e [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:13.467832  1533 sys_catalog.cc:458] T 00000000000000000000000000000000 P 277b10ab22cd41afb3fee1089520fe6e [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:13.468415  1422 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:18:13.470314  1550 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 277b10ab22cd41afb3fee1089520fe6e: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:18:13.470377  1550 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:18:13.470453  1545 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:13.471360  1545 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:13.475996  1545 catalog_manager.cc:1383] Generated new cluster ID: 69257f9e7a0c417caa4f247ec9d41272
I20260812 06:18:13.476065  1545 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:13.484975  1545 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:13.485809  1545 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:13.491436  1545 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 277b10ab22cd41afb3fee1089520fe6e: Generated new TSK 0
I20260812 06:18:13.492094  1545 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:13.501240  1422 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:13.504274  1560 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:18:13.504242  1561 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:18:13.504248  1563 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:18:13.504494  1422 server_base.cc:1061] running on GCE node
I20260812 06:18:13.504892  1422 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:13.504958  1422 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:18:13.504987  1422 hybrid_clock.cc:648] HybridClock initialized: now 1786515493504986 us; error 0 us; skew 500 ppm
I20260812 06:18:13.506001  1422 webserver.cc:533] Webserver started at http://127.1.99.129:33709/ using document root <none> and password file <none>
I20260812 06:18:13.506189  1422 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:13.506260  1422 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:13.506341  1422 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:13.506815  1422 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root/instance:
uuid: "1124031c904c41ae9592b3bf7d722174"
format_stamp: "Formatted at 2026-08-12 06:18:13 on dist-test-slave-3kk6"
I20260812 06:18:13.508414  1422 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:13.509475  1572 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:18:13.509768  1422 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:13.509860  1422 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root
uuid: "1124031c904c41ae9592b3bf7d722174"
format_stamp: "Formatted at 2026-08-12 06:18:13 on dist-test-slave-3kk6"
I20260812 06:18:13.509953  1422 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-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:18:13.525961  1422 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:13.526475  1422 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:13.527122  1422 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:13.528080  1422 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:13.528134  1422 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:13.528203  1422 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:13.528247  1422 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:13.535475  1422 rpc_server.cc:307] RPC server started. Bound to: 127.1.99.129:46867
I20260812 06:18:13.535511  1685 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.1.99.129:46867 every 8 connection(s)
I20260812 06:18:13.549235  1686 heartbeater.cc:344] Connected to a master server at 127.1.99.190:43113
I20260812 06:18:13.549567  1686 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:13.550081  1686 heartbeater.cc:507] Master 127.1.99.190:43113 requested a full tablet report, sending...
I20260812 06:18:13.551733  1475 ts_manager.cc:194] Registered new tserver with Master: 1124031c904c41ae9592b3bf7d722174 (127.1.99.129:46867)
I20260812 06:18:13.551872  1422 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01570093s
I20260812 06:18:13.553328  1475 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:35724
I20260812 06:18:13.562525  1475 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:35740:
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:18:13.578347  1612 tablet_service.cc:1511] Processing CreateTablet for tablet 8e5160f45f2048ef92fa3b681474992f (DEFAULT_TABLE table=heavy-update-compaction-test [id=22d0c69374e74eb8a96127d55d0c2c4a]), partition=
I20260812 06:18:13.578899  1612 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 8e5160f45f2048ef92fa3b681474992f. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:13.581743  1705 tablet_bootstrap.cc:492] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Bootstrap starting.
I20260812 06:18:13.582845  1705 tablet_bootstrap.cc:654] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:13.584146  1705 tablet_bootstrap.cc:492] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: No bootstrap required, opened a new log
I20260812 06:18:13.584272  1705 ts_tablet_manager.cc:1403] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Time spent bootstrapping tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:18:13.584751  1705 raft_consensus.cc:359] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1124031c904c41ae9592b3bf7d722174" member_type: VOTER last_known_addr { host: "127.1.99.129" port: 46867 } }
I20260812 06:18:13.584867  1705 raft_consensus.cc:385] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:13.584892  1705 raft_consensus.cc:740] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 1124031c904c41ae9592b3bf7d722174, State: Initialized, Role: FOLLOWER
I20260812 06:18:13.585035  1705 consensus_queue.cc:260] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174 [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: "1124031c904c41ae9592b3bf7d722174" member_type: VOTER last_known_addr { host: "127.1.99.129" port: 46867 } }
I20260812 06:18:13.585108  1705 raft_consensus.cc:399] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:13.585168  1705 raft_consensus.cc:493] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:13.585222  1705 raft_consensus.cc:3060] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:13.586243  1705 raft_consensus.cc:515] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1124031c904c41ae9592b3bf7d722174" member_type: VOTER last_known_addr { host: "127.1.99.129" port: 46867 } }
I20260812 06:18:13.586400  1705 leader_election.cc:304] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174 [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: 1124031c904c41ae9592b3bf7d722174; no voters: 
I20260812 06:18:13.586653  1705 leader_election.cc:290] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:13.586799  1707 raft_consensus.cc:2804] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:13.587055  1707 raft_consensus.cc:697] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174 [term 1 LEADER]: Becoming Leader. State: Replica: 1124031c904c41ae9592b3bf7d722174, State: Running, Role: LEADER
I20260812 06:18:13.587198  1705 ts_tablet_manager.cc:1434] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:18:13.587246  1707 consensus_queue.cc:237] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174 [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: "1124031c904c41ae9592b3bf7d722174" member_type: VOTER last_known_addr { host: "127.1.99.129" port: 46867 } }
I20260812 06:18:13.587718  1686 heartbeater.cc:499] Master 127.1.99.190:43113 was elected leader, sending a full tablet report...
I20260812 06:18:13.590497  1475 catalog_manager.cc:5719] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174 reported cstate change: term changed from 0 to 1, leader changed from <none> to 1124031c904c41ae9592b3bf7d722174 (127.1.99.129). New cstate: current_term: 1 leader_uuid: "1124031c904c41ae9592b3bf7d722174" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1124031c904c41ae9592b3bf7d722174" member_type: VOTER last_known_addr { host: "127.1.99.129" port: 46867 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:13.661118  1422 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.061s	user 0.012s	sys 0.017s
I20260812 06:18:13.786818  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushMRSOp(8e5160f45f2048ef92fa3b681474992f): perf score=15.086190
I20260812 06:18:13.953243  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushMRSOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.166s	user 0.097s	sys 0.061s Metrics: {"bytes_written":13045927,"cfile_init":1,"compiler_manager_pool.queue_time_us":199,"delete_count":0,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":306,"dirs.run_wall_time_us":948,"drs_written":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42349,"lbm_writes_lt_1ms":685,"mutex_wait_us":189,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":174336,"thread_start_us":123,"threads_started":1,"update_count":1590}
I20260812 06:18:13.954542  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling UndoDeltaBlockGCOp(8e5160f45f2048ef92fa3b681474992f): 12719231 bytes on disk
I20260812 06:18:13.955181  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: UndoDeltaBlockGCOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4}
I20260812 06:18:13.955637  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=3.181125
I20260812 06:18:13.973958  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.018s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4348810,"delete_count":0,"lbm_write_time_us":7190,"lbm_writes_lt_1ms":109,"reinsert_count":0,"update_count":530}
I20260812 06:18:13.974545  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling LogGCOp(8e5160f45f2048ef92fa3b681474992f): free 20743880 bytes of WAL
I20260812 06:18:13.974949  1579 log_reader.cc:385] T 8e5160f45f2048ef92fa3b681474992f: removed 2 log segments from log reader
I20260812 06:18:13.975066  1579 log.cc:1079] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/8e5160f45f2048ef92fa3b681474992f/wal-000000001 (ops 1-6)
I20260812 06:18:13.975160  1579 log.cc:1079] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/8e5160f45f2048ef92fa3b681474992f/wal-000000002 (ops 7-11)
I20260812 06:18:13.979794  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: LogGCOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.005s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:18:13.980134  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=1.196750
I20260812 06:18:13.988742  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.008s	user 0.006s	sys 0.001s Metrics: {"bytes_written":2707805,"delete_count":0,"lbm_write_time_us":2636,"lbm_writes_lt_1ms":69,"reinsert_count":0,"update_count":330}
I20260812 06:18:13.989452  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling MajorDeltaCompactionOp(8e5160f45f2048ef92fa3b681474992f): perf score=1.000000
I20260812 06:18:14.164139  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: MajorDeltaCompactionOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.174s	user 0.127s	sys 0.043s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24364542,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":945,"lbm_read_time_us":11859,"lbm_reads_lt_1ms":559,"lbm_write_time_us":31225,"lbm_writes_lt_1ms":533,"mutex_wait_us":3,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":1920,"thread_start_us":342,"threads_started":5,"update_count":2450}
I20260812 06:18:14.164692  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=10.126437
I20260812 06:18:14.206575  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.042s	user 0.007s	sys 0.031s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16154,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:14.207258  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=2.188937
I20260812 06:18:14.219998  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4727,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:14.220485  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling MajorDeltaCompactionOp(8e5160f45f2048ef92fa3b681474992f): perf score=1.000000
I20260812 06:18:14.350353  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: MajorDeltaCompactionOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.130s	user 0.072s	sys 0.056s 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":386,"lbm_read_time_us":8356,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25804,"lbm_writes_lt_1ms":443,"mutex_wait_us":20,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2000}
I20260812 06:18:14.351016  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=10.126437
I20260812 06:18:14.395855  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.045s	user 0.024s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17966,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:14.396369  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=2.188937
I20260812 06:18:14.407366  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3997,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:14.408034  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling MajorDeltaCompactionOp(8e5160f45f2048ef92fa3b681474992f): perf score=1.000000
I20260812 06:18:14.538518  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: MajorDeltaCompactionOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.130s	user 0.114s	sys 0.015s 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":522,"lbm_read_time_us":9923,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24158,"lbm_writes_lt_1ms":443,"mutex_wait_us":44,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2000}
I20260812 06:18:14.539232  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=10.126437
I20260812 06:18:14.596448  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.057s	user 0.032s	sys 0.023s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":22549,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:14.597095  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=2.188937
I20260812 06:18:14.608289  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4366,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:14.608811  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling MajorDeltaCompactionOp(8e5160f45f2048ef92fa3b681474992f): perf score=1.000000
I20260812 06:18:14.773818  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: MajorDeltaCompactionOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.165s	user 0.101s	sys 0.063s 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":1001,"lbm_read_time_us":12571,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28661,"lbm_writes_lt_1ms":443,"mutex_wait_us":42,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":2000}
I20260812 06:18:14.774500  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=10.126437
I20260812 06:18:14.821365  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.047s	user 0.018s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19520,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:14.821946  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=2.188937
I20260812 06:18:14.833935  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4131,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:14.834736  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling MajorDeltaCompactionOp(8e5160f45f2048ef92fa3b681474992f): perf score=1.000000
I20260812 06:18:14.959041  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: MajorDeltaCompactionOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.124s	user 0.078s	sys 0.045s 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":908,"lbm_read_time_us":8708,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24065,"lbm_writes_lt_1ms":443,"mutex_wait_us":52,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":2000}
I20260812 06:18:14.959676  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=10.126437
I20260812 06:18:15.009311  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.049s	user 0.026s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":25423,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:15.009861  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=2.188937
I20260812 06:18:15.021669  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4169,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.022143  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling MajorDeltaCompactionOp(8e5160f45f2048ef92fa3b681474992f): perf score=1.000000
I20260812 06:18:15.156283  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: MajorDeltaCompactionOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.134s	user 0.100s	sys 0.033s 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":277,"lbm_read_time_us":10170,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27987,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2000}
I20260812 06:18:15.156895  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=10.126437
I20260812 06:18:15.213738  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.057s	user 0.021s	sys 0.032s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21177,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:15.214263  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=2.188937
I20260812 06:18:15.224879  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4142,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.225351  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushMRSOp(8e5160f45f2048ef92fa3b681474992f): perf score=1.000000
I20260812 06:18:15.254906  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushMRSOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.029s	user 0.026s	sys 0.003s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":253,"dirs.run_wall_time_us":1351,"drs_written":1,"lbm_read_time_us":128,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1480,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:15.255791  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling UndoDeltaBlockGCOp(8e5160f45f2048ef92fa3b681474992f): 447 bytes on disk
I20260812 06:18:15.256294  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: UndoDeltaBlockGCOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":80,"lbm_reads_lt_1ms":4}
I20260812 06:18:15.256762  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling MajorDeltaCompactionOp(8e5160f45f2048ef92fa3b681474992f): perf score=1.000000
I20260812 06:18:15.402624  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: MajorDeltaCompactionOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.146s	user 0.110s	sys 0.036s 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":387,"lbm_read_time_us":9814,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26047,"lbm_writes_lt_1ms":443,"mutex_wait_us":57,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:15.403328  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling LogGCOp(8e5160f45f2048ef92fa3b681474992f): free 112239287 bytes of WAL
I20260812 06:18:15.403651  1579 log_reader.cc:385] T 8e5160f45f2048ef92fa3b681474992f: removed 11 log segments from log reader
I20260812 06:18:15.403734  1579 log.cc:1079] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/8e5160f45f2048ef92fa3b681474992f/wal-000000003 (ops 12-16)
I20260812 06:18:15.403787  1579 log.cc:1079] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/8e5160f45f2048ef92fa3b681474992f/wal-000000004 (ops 17-21)
I20260812 06:18:15.403842  1579 log.cc:1079] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/8e5160f45f2048ef92fa3b681474992f/wal-000000005 (ops 22-26)
I20260812 06:18:15.403885  1579 log.cc:1079] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/8e5160f45f2048ef92fa3b681474992f/wal-000000006 (ops 27-30)
I20260812 06:18:15.403928  1579 log.cc:1079] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/8e5160f45f2048ef92fa3b681474992f/wal-000000007 (ops 31-35)
I20260812 06:18:15.403971  1579 log.cc:1079] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/8e5160f45f2048ef92fa3b681474992f/wal-000000008 (ops 36-40)
I20260812 06:18:15.404014  1579 log.cc:1079] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/8e5160f45f2048ef92fa3b681474992f/wal-000000009 (ops 41-45)
I20260812 06:18:15.404059  1579 log.cc:1079] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/8e5160f45f2048ef92fa3b681474992f/wal-000000010 (ops 46-50)
I20260812 06:18:15.404103  1579 log.cc:1079] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/8e5160f45f2048ef92fa3b681474992f/wal-000000011 (ops 51-55)
I20260812 06:18:15.404146  1579 log.cc:1079] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/8e5160f45f2048ef92fa3b681474992f/wal-000000012 (ops 56-60)
I20260812 06:18:15.404191  1579 log.cc:1079] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/8e5160f45f2048ef92fa3b681474992f/wal-000000013 (ops 61-65)
I20260812 06:18:15.432120  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: LogGCOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.029s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:18:15.432581  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=14.095187
I20260812 06:18:15.481581  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.049s	user 0.031s	sys 0.014s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":22187,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:15.482054  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=2.188937
I20260812 06:18:15.494860  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.013s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4131,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.495362  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling MajorDeltaCompactionOp(8e5160f45f2048ef92fa3b681474992f): perf score=1.000000
I20260812 06:18:15.654872  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: MajorDeltaCompactionOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.159s	user 0.132s	sys 0.026s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":219,"lbm_read_time_us":11883,"lbm_reads_lt_1ms":564,"lbm_write_time_us":32367,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2500}
I20260812 06:18:15.655400  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=11.118625
I20260812 06:18:15.697754  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.042s	user 0.030s	sys 0.009s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":18755,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:15.698465  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=2.188937
I20260812 06:18:15.711076  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4615,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:15.711666  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling MajorDeltaCompactionOp(8e5160f45f2048ef92fa3b681474992f): perf score=1.000000
I20260812 06:18:15.844106  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: MajorDeltaCompactionOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.132s	user 0.105s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672270,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":172,"lbm_read_time_us":8856,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27565,"lbm_writes_lt_1ms":443,"mutex_wait_us":72,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:15.846310  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=11.118625
I20260812 06:18:15.893030  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.046s	user 0.021s	sys 0.023s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":20376,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:15.893719  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=2.188937
I20260812 06:18:15.920562  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.027s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5348,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:15.921054  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=2.188937
I20260812 06:18:15.931766  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4110,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.932320  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling MajorDeltaCompactionOp(8e5160f45f2048ef92fa3b681474992f): perf score=1.000000
I20260812 06:18:16.102223  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: MajorDeltaCompactionOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.170s	user 0.109s	sys 0.055s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":329,"lbm_read_time_us":11283,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32827,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:16.103655  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=13.103000
I20260812 06:18:16.148123  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.044s	user 0.031s	sys 0.012s Metrics: {"bytes_written":15015083,"delete_count":0,"lbm_write_time_us":18926,"lbm_writes_lt_1ms":369,"reinsert_count":0,"update_count":1830}
I20260812 06:18:16.148684  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=1.000000
I20260812 06:18:16.166955  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.018s	user 0.005s	sys 0.000s Metrics: {"bytes_written":1395002,"delete_count":0,"lbm_write_time_us":1487,"lbm_writes_lt_1ms":37,"reinsert_count":0,"update_count":170}
I20260812 06:18:16.167479  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=2.188937
I20260812 06:18:16.178375  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4177,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.178913  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling MajorDeltaCompactionOp(8e5160f45f2048ef92fa3b681474992f): perf score=1.000000
I20260812 06:18:16.365983  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: MajorDeltaCompactionOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.187s	user 0.127s	sys 0.058s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774745,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":292,"lbm_read_time_us":13234,"lbm_reads_lt_1ms":573,"lbm_write_time_us":33178,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":2500}
I20260812 06:18:16.366817  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=14.095187
I20260812 06:18:16.414299  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.047s	user 0.025s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20525,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:16.414906  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling MajorDeltaCompactionOp(8e5160f45f2048ef92fa3b681474992f): perf score=1.000000
I20260812 06:18:16.590679  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: MajorDeltaCompactionOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.176s	user 0.086s	sys 0.085s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":166,"lbm_read_time_us":9968,"lbm_reads_lt_1ms":463,"lbm_write_time_us":31517,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18944,"update_count":2000}
I20260812 06:18:16.591300  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=14.095187
I20260812 06:18:16.640297  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.049s	user 0.034s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19051,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:16.640913  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=2.188937
I20260812 06:18:16.657668  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.017s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6247,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.658321  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushMRSOp(8e5160f45f2048ef92fa3b681474992f): perf score=1.000000
I20260812 06:18:16.693338  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushMRSOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.035s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":230,"dirs.run_wall_time_us":1327,"drs_written":1,"lbm_read_time_us":127,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2147,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:16.694571  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=2.188937
I20260812 06:18:16.709765  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5968,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.710397  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling LogGCOp(8e5160f45f2048ef92fa3b681474992f): free 112239374 bytes of WAL
I20260812 06:18:16.710789  1579 log_reader.cc:385] T 8e5160f45f2048ef92fa3b681474992f: removed 11 log segments from log reader
I20260812 06:18:16.710860  1579 log.cc:1079] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/8e5160f45f2048ef92fa3b681474992f/wal-000000014 (ops 66-70)
I20260812 06:18:16.710916  1579 log.cc:1079] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/8e5160f45f2048ef92fa3b681474992f/wal-000000015 (ops 71-75)
I20260812 06:18:16.710968  1579 log.cc:1079] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/8e5160f45f2048ef92fa3b681474992f/wal-000000016 (ops 76-80)
I20260812 06:18:16.711010  1579 log.cc:1079] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/8e5160f45f2048ef92fa3b681474992f/wal-000000017 (ops 81-85)
I20260812 06:18:16.711050  1579 log.cc:1079] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/8e5160f45f2048ef92fa3b681474992f/wal-000000018 (ops 86-90)
I20260812 06:18:16.711086  1579 log.cc:1079] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/8e5160f45f2048ef92fa3b681474992f/wal-000000019 (ops 91-94)
I20260812 06:18:16.711124  1579 log.cc:1079] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/8e5160f45f2048ef92fa3b681474992f/wal-000000020 (ops 95-99)
I20260812 06:18:16.711161  1579 log.cc:1079] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/8e5160f45f2048ef92fa3b681474992f/wal-000000021 (ops 100-104)
I20260812 06:18:16.711198  1579 log.cc:1079] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/8e5160f45f2048ef92fa3b681474992f/wal-000000022 (ops 105-109)
I20260812 06:18:16.711234  1579 log.cc:1079] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/8e5160f45f2048ef92fa3b681474992f/wal-000000023 (ops 110-114)
I20260812 06:18:16.711270  1579 log.cc:1079] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/8e5160f45f2048ef92fa3b681474992f/wal-000000024 (ops 115-119)
I20260812 06:18:16.738373  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: LogGCOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.028s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:18:16.738909  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling UndoDeltaBlockGCOp(8e5160f45f2048ef92fa3b681474992f): 447 bytes on disk
I20260812 06:18:16.739509  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: UndoDeltaBlockGCOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4}
I20260812 06:18:16.740185  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling MajorDeltaCompactionOp(8e5160f45f2048ef92fa3b681474992f): perf score=1.000000
I20260812 06:18:16.942915  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: MajorDeltaCompactionOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.203s	user 0.122s	sys 0.077s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877220,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":636,"lbm_read_time_us":13610,"lbm_reads_lt_1ms":665,"lbm_write_time_us":34160,"lbm_writes_lt_1ms":643,"mutex_wait_us":106,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":84,"threads_started":1,"update_count":3000}
I20260812 06:18:16.943756  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=18.063937
I20260812 06:18:17.011518  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.067s	user 0.035s	sys 0.031s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":24486,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:17.012204  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=2.188937
I20260812 06:18:17.030000  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.018s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6697,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.030676  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling MajorDeltaCompactionOp(8e5160f45f2048ef92fa3b681474992f): perf score=1.000000
I20260812 06:18:17.233206  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: MajorDeltaCompactionOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.202s	user 0.149s	sys 0.053s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":67,"lbm_read_time_us":15743,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33070,"lbm_writes_lt_1ms":643,"mutex_wait_us":24,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":3000}
I20260812 06:18:17.233942  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=14.095187
I20260812 06:18:17.282105  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.048s	user 0.024s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22084,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:17.282886  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=2.188937
I20260812 06:18:17.299887  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.017s	user 0.015s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6687,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.300460  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling MajorDeltaCompactionOp(8e5160f45f2048ef92fa3b681474992f): perf score=1.000000
I20260812 06:18:17.481020  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: MajorDeltaCompactionOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.180s	user 0.140s	sys 0.040s 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":1298,"lbm_read_time_us":13081,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29753,"lbm_writes_lt_1ms":543,"mutex_wait_us":349,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2500}
I20260812 06:18:17.481761  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=14.095187
I20260812 06:18:17.544570  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.063s	user 0.030s	sys 0.026s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20639,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:17.545181  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=2.188937
I20260812 06:18:17.561923  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.017s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6707,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.562482  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling MajorDeltaCompactionOp(8e5160f45f2048ef92fa3b681474992f): perf score=1.000000
I20260812 06:18:17.747008  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: MajorDeltaCompactionOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.184s	user 0.133s	sys 0.049s 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":1274,"lbm_read_time_us":13683,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30787,"lbm_writes_lt_1ms":543,"mutex_wait_us":64,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:18:17.747531  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=11.118625
I20260812 06:18:17.782059  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.034s	user 0.014s	sys 0.017s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":14681,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:17.782748  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=2.188937
I20260812 06:18:17.814764  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.032s	user 0.010s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5038,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:17.815264  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=2.188937
I20260812 06:18:17.826181  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.011s	user 0.000s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4319,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.826792  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling MajorDeltaCompactionOp(8e5160f45f2048ef92fa3b681474992f): perf score=1.000000
I20260812 06:18:18.005971  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: MajorDeltaCompactionOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.179s	user 0.118s	sys 0.060s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774801,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":886,"lbm_read_time_us":12581,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31424,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6272,"update_count":2500}
I20260812 06:18:18.006549  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=14.095187
I20260812 06:18:18.051445  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.045s	user 0.035s	sys 0.008s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19499,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:18:18.052073  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=2.188937
I20260812 06:18:18.079320  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.027s	user 0.007s	sys 0.020s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6059,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.080166  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling MajorDeltaCompactionOp(8e5160f45f2048ef92fa3b681474992f): perf score=1.000000
I20260812 06:18:18.276577  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: MajorDeltaCompactionOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.196s	user 0.109s	sys 0.075s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1043,"lbm_read_time_us":13660,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31720,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2500}
I20260812 06:18:18.277345  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=14.095187
I20260812 06:18:18.330054  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.052s	user 0.036s	sys 0.009s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21256,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:18.330766  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=2.188937
I20260812 06:18:18.343561  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.013s	user 0.002s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5096,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.344166  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushMRSOp(8e5160f45f2048ef92fa3b681474992f): perf score=1.000000
I20260812 06:18:18.386327  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushMRSOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.042s	user 0.025s	sys 0.013s Metrics: {"bytes_written":1316414,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":303,"dirs.run_wall_time_us":1388,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1772,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:18.387657  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling LogGCOp(8e5160f45f2048ef92fa3b681474992f): free 141338690 bytes of WAL
I20260812 06:18:18.388025  1579 log_reader.cc:385] T 8e5160f45f2048ef92fa3b681474992f: removed 14 log segments from log reader
I20260812 06:18:18.388098  1579 log.cc:1079] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/8e5160f45f2048ef92fa3b681474992f/wal-000000025 (ops 120-124)
I20260812 06:18:18.388216  1579 log.cc:1079] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/8e5160f45f2048ef92fa3b681474992f/wal-000000026 (ops 125-128)
I20260812 06:18:18.388267  1579 log.cc:1079] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/8e5160f45f2048ef92fa3b681474992f/wal-000000027 (ops 129-133)
I20260812 06:18:18.388299  1579 log.cc:1079] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/8e5160f45f2048ef92fa3b681474992f/wal-000000028 (ops 134-138)
I20260812 06:18:18.388378  1579 log.cc:1079] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/8e5160f45f2048ef92fa3b681474992f/wal-000000029 (ops 139-143)
I20260812 06:18:18.388430  1579 log.cc:1079] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/8e5160f45f2048ef92fa3b681474992f/wal-000000030 (ops 144-148)
I20260812 06:18:18.388499  1579 log.cc:1079] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/8e5160f45f2048ef92fa3b681474992f/wal-000000031 (ops 149-153)
I20260812 06:18:18.388537  1579 log.cc:1079] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/8e5160f45f2048ef92fa3b681474992f/wal-000000032 (ops 154-158)
I20260812 06:18:18.388607  1579 log.cc:1079] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/8e5160f45f2048ef92fa3b681474992f/wal-000000033 (ops 159-163)
I20260812 06:18:18.388657  1579 log.cc:1079] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/8e5160f45f2048ef92fa3b681474992f/wal-000000034 (ops 164-168)
I20260812 06:18:18.388700  1579 log.cc:1079] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/8e5160f45f2048ef92fa3b681474992f/wal-000000035 (ops 169-172)
I20260812 06:18:18.388758  1579 log.cc:1079] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/8e5160f45f2048ef92fa3b681474992f/wal-000000036 (ops 173-177)
I20260812 06:18:18.388814  1579 log.cc:1079] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/8e5160f45f2048ef92fa3b681474992f/wal-000000037 (ops 178-182)
I20260812 06:18:18.388891  1579 log.cc:1079] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/8e5160f45f2048ef92fa3b681474992f/wal-000000038 (ops 183-187)
I20260812 06:18:18.422547  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: LogGCOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.035s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:18:18.423400  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=5.165500
I20260812 06:18:18.439070  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.015s	user 0.008s	sys 0.007s Metrics: {"bytes_written":6400021,"delete_count":0,"lbm_write_time_us":6427,"lbm_writes_lt_1ms":159,"reinsert_count":0,"update_count":780}
I20260812 06:18:18.439589  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling UndoDeltaBlockGCOp(8e5160f45f2048ef92fa3b681474992f): 492 bytes on disk
I20260812 06:18:18.440022  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: UndoDeltaBlockGCOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:18:18.440549  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=1.000000
I20260812 06:18:18.447326  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.007s	user 0.004s	sys 0.002s Metrics: {"bytes_written":1805252,"delete_count":0,"lbm_write_time_us":1890,"lbm_writes_lt_1ms":47,"reinsert_count":0,"update_count":220}
I20260812 06:18:18.447954  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling MajorDeltaCompactionOp(8e5160f45f2048ef92fa3b681474992f): perf score=1.000000
I20260812 06:18:18.700112  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: MajorDeltaCompactionOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.252s	user 0.160s	sys 0.080s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979702,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":682,"lbm_read_time_us":16501,"lbm_reads_lt_1ms":774,"lbm_write_time_us":42869,"lbm_writes_lt_1ms":743,"mutex_wait_us":49,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":117,"threads_started":1,"update_count":3500}
I20260812 06:18:18.701550  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f): perf score=18.063937
I20260812 06:18:18.763299  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: FlushDeltaMemStoresOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.061s	user 0.030s	sys 0.027s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":26721,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:18.763832  1687 maintenance_manager.cc:419] P 1124031c904c41ae9592b3bf7d722174: Scheduling MajorDeltaCompactionOp(8e5160f45f2048ef92fa3b681474992f): perf score=1.000000
I20260812 06:18:18.771930  1422 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.111s	user 1.877s	sys 0.195s
I20260812 06:18:18.852864  1422 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.080s	user 0.001s	sys 0.000s
I20260812 06:18:18.853600  1422 tablet_server.cc:179] TabletServer@127.1.99.129:0 shutting down...
I20260812 06:18:18.916626  1579 maintenance_manager.cc:643] P 1124031c904c41ae9592b3bf7d722174: MajorDeltaCompactionOp(8e5160f45f2048ef92fa3b681474992f) complete. Timing: real 0.153s	user 0.089s	sys 0.063s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24774572,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":849,"lbm_read_time_us":14175,"lbm_reads_lt_1ms":559,"lbm_write_time_us":25925,"lbm_writes_lt_1ms":543,"mutex_wait_us":304,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":79616,"update_count":2500}
I20260812 06:18:18.917347  1422 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:18.917797  1422 tablet_replica.cc:333] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174: stopping tablet replica
I20260812 06:18:18.918054  1422 raft_consensus.cc:2243] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:18.918298  1422 raft_consensus.cc:2272] T 8e5160f45f2048ef92fa3b681474992f P 1124031c904c41ae9592b3bf7d722174 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:18.935000  1422 tablet_server.cc:196] TabletServer@127.1.99.129:0 shutdown complete.
I20260812 06:18:18.963681  1422 master.cc:562] Master@127.1.99.190:43113 shutting down...
I20260812 06:18:18.968570  1422 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 277b10ab22cd41afb3fee1089520fe6e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:18.968782  1422 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 277b10ab22cd41afb3fee1089520fe6e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:18.968847  1422 tablet_replica.cc:333] T 00000000000000000000000000000000 P 277b10ab22cd41afb3fee1089520fe6e: stopping tablet replica
I20260812 06:18:18.981534  1422 master.cc:584] Master@127.1.99.190:43113 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5684 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:19.101742  1422 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.1.99.190:33407
I20260812 06:18:19.102181  1422 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:19.104960  1737 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:18:19.104981  1422 server_base.cc:1061] running on GCE node
W20260812 06:18:19.105062  1732 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:18:19.105085  1729 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:18:19.105549  1422 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:19.105611  1422 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:18:19.105630  1422 hybrid_clock.cc:648] HybridClock initialized: now 1786515499105630 us; error 0 us; skew 500 ppm
I20260812 06:18:19.106583  1422 webserver.cc:533] Webserver started at http://127.1.99.190:44253/ using document root <none> and password file <none>
I20260812 06:18:19.106822  1422 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:19.106894  1422 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:19.106987  1422 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:19.107525  1422 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/master-0-root/instance:
uuid: "9cd201b671ec496e8ee70804960e234e"
format_stamp: "Formatted at 2026-08-12 06:18:19 on dist-test-slave-3kk6"
I20260812 06:18:19.109290  1422 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:19.110412  1746 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:18:19.110770  1422 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:19.110853  1422 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/master-0-root
uuid: "9cd201b671ec496e8ee70804960e234e"
format_stamp: "Formatted at 2026-08-12 06:18:19 on dist-test-slave-3kk6"
I20260812 06:18:19.110963  1422 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-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:18:19.123692  1422 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:19.124187  1422 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:19.129290  1422 rpc_server.cc:307] RPC server started. Bound to: 127.1.99.190:33407
I20260812 06:18:19.133859  1831 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.1.99.190:33407 every 8 connection(s)
I20260812 06:18:19.134407  1832 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:18:19.136509  1832 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 9cd201b671ec496e8ee70804960e234e: Bootstrap starting.
I20260812 06:18:19.137387  1832 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 9cd201b671ec496e8ee70804960e234e: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:19.138602  1832 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 9cd201b671ec496e8ee70804960e234e: No bootstrap required, opened a new log
I20260812 06:18:19.139130  1832 raft_consensus.cc:359] T 00000000000000000000000000000000 P 9cd201b671ec496e8ee70804960e234e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9cd201b671ec496e8ee70804960e234e" member_type: VOTER }
I20260812 06:18:19.139222  1832 raft_consensus.cc:385] T 00000000000000000000000000000000 P 9cd201b671ec496e8ee70804960e234e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:19.139245  1832 raft_consensus.cc:740] T 00000000000000000000000000000000 P 9cd201b671ec496e8ee70804960e234e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 9cd201b671ec496e8ee70804960e234e, State: Initialized, Role: FOLLOWER
I20260812 06:18:19.139463  1832 consensus_queue.cc:260] T 00000000000000000000000000000000 P 9cd201b671ec496e8ee70804960e234e [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: "9cd201b671ec496e8ee70804960e234e" member_type: VOTER }
I20260812 06:18:19.139554  1832 raft_consensus.cc:399] T 00000000000000000000000000000000 P 9cd201b671ec496e8ee70804960e234e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:19.139611  1832 raft_consensus.cc:493] T 00000000000000000000000000000000 P 9cd201b671ec496e8ee70804960e234e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:19.139669  1832 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 9cd201b671ec496e8ee70804960e234e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:19.140434  1832 raft_consensus.cc:515] T 00000000000000000000000000000000 P 9cd201b671ec496e8ee70804960e234e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9cd201b671ec496e8ee70804960e234e" member_type: VOTER }
I20260812 06:18:19.140579  1832 leader_election.cc:304] T 00000000000000000000000000000000 P 9cd201b671ec496e8ee70804960e234e [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: 9cd201b671ec496e8ee70804960e234e; no voters: 
I20260812 06:18:19.140828  1832 leader_election.cc:290] T 00000000000000000000000000000000 P 9cd201b671ec496e8ee70804960e234e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:19.141067  1840 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 9cd201b671ec496e8ee70804960e234e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:19.141309  1840 raft_consensus.cc:697] T 00000000000000000000000000000000 P 9cd201b671ec496e8ee70804960e234e [term 1 LEADER]: Becoming Leader. State: Replica: 9cd201b671ec496e8ee70804960e234e, State: Running, Role: LEADER
I20260812 06:18:19.141422  1832 sys_catalog.cc:565] T 00000000000000000000000000000000 P 9cd201b671ec496e8ee70804960e234e [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:19.141500  1840 consensus_queue.cc:237] T 00000000000000000000000000000000 P 9cd201b671ec496e8ee70804960e234e [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: "9cd201b671ec496e8ee70804960e234e" member_type: VOTER }
I20260812 06:18:19.142083  1843 sys_catalog.cc:455] T 00000000000000000000000000000000 P 9cd201b671ec496e8ee70804960e234e [sys.catalog]: SysCatalogTable state changed. Reason: New leader 9cd201b671ec496e8ee70804960e234e. Latest consensus state: current_term: 1 leader_uuid: "9cd201b671ec496e8ee70804960e234e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9cd201b671ec496e8ee70804960e234e" member_type: VOTER } }
I20260812 06:18:19.142194  1843 sys_catalog.cc:458] T 00000000000000000000000000000000 P 9cd201b671ec496e8ee70804960e234e [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:19.142359  1841 sys_catalog.cc:455] T 00000000000000000000000000000000 P 9cd201b671ec496e8ee70804960e234e [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "9cd201b671ec496e8ee70804960e234e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9cd201b671ec496e8ee70804960e234e" member_type: VOTER } }
I20260812 06:18:19.142444  1841 sys_catalog.cc:458] T 00000000000000000000000000000000 P 9cd201b671ec496e8ee70804960e234e [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:19.142912  1853 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:19.143731  1853 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:19.143941  1422 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:19.146020  1853 catalog_manager.cc:1383] Generated new cluster ID: 355ee8ff71894f25a0c3e60e6d54e67b
I20260812 06:18:19.146087  1853 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:19.159368  1853 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:19.160059  1853 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:19.171665  1853 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 9cd201b671ec496e8ee70804960e234e: Generated new TSK 0
I20260812 06:18:19.171952  1853 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:19.176376  1422 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:19.178857  1872 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:18:19.178954  1422 server_base.cc:1061] running on GCE node
W20260812 06:18:19.178795  1873 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:18:19.178817  1875 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:18:19.179327  1422 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:19.179396  1422 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:18:19.179425  1422 hybrid_clock.cc:648] HybridClock initialized: now 1786515499179425 us; error 0 us; skew 500 ppm
I20260812 06:18:19.180383  1422 webserver.cc:533] Webserver started at http://127.1.99.129:36355/ using document root <none> and password file <none>
I20260812 06:18:19.180585  1422 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:19.180665  1422 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:19.180751  1422 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:19.181178  1422 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root/instance:
uuid: "7f6fed4bb83f4e3a9d5408e3afa00558"
format_stamp: "Formatted at 2026-08-12 06:18:19 on dist-test-slave-3kk6"
I20260812 06:18:19.182890  1422 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:19.183955  1884 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:18:19.184231  1422 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:19.184341  1422 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root
uuid: "7f6fed4bb83f4e3a9d5408e3afa00558"
format_stamp: "Formatted at 2026-08-12 06:18:19 on dist-test-slave-3kk6"
I20260812 06:18:19.184433  1422 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-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:18:19.204789  1422 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:19.205372  1422 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:19.205766  1422 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:19.206326  1422 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:19.206393  1422 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:19.206457  1422 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:19.206508  1422 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:19.211650  1422 rpc_server.cc:307] RPC server started. Bound to: 127.1.99.129:34103
I20260812 06:18:19.211761  1983 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.1.99.129:34103 every 8 connection(s)
I20260812 06:18:19.220921  1985 heartbeater.cc:344] Connected to a master server at 127.1.99.190:33407
I20260812 06:18:19.221055  1985 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:19.221443  1985 heartbeater.cc:507] Master 127.1.99.190:33407 requested a full tablet report, sending...
I20260812 06:18:19.222216  1775 ts_manager.cc:194] Registered new tserver with Master: 7f6fed4bb83f4e3a9d5408e3afa00558 (127.1.99.129:34103)
I20260812 06:18:19.222452  1422 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.010199916s
I20260812 06:18:19.223315  1775 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:47978
I20260812 06:18:19.230206  1775 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:47992:
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:18:19.239423  1926 tablet_service.cc:1511] Processing CreateTablet for tablet 90ca010d615d4b8998e9aef192da5042 (DEFAULT_TABLE table=heavy-update-compaction-test [id=bf39ac170b8b4bf88dbbadf13fcdb15b]), partition=
I20260812 06:18:19.239759  1926 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 90ca010d615d4b8998e9aef192da5042. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:19.242087  2008 tablet_bootstrap.cc:492] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Bootstrap starting.
I20260812 06:18:19.243150  2008 tablet_bootstrap.cc:654] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:19.244431  2008 tablet_bootstrap.cc:492] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: No bootstrap required, opened a new log
I20260812 06:18:19.244542  2008 ts_tablet_manager.cc:1403] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Time spent bootstrapping tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:18:19.245101  2008 raft_consensus.cc:359] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7f6fed4bb83f4e3a9d5408e3afa00558" member_type: VOTER last_known_addr { host: "127.1.99.129" port: 34103 } }
I20260812 06:18:19.245194  2008 raft_consensus.cc:385] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:19.245217  2008 raft_consensus.cc:740] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 7f6fed4bb83f4e3a9d5408e3afa00558, State: Initialized, Role: FOLLOWER
I20260812 06:18:19.245355  2008 consensus_queue.cc:260] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558 [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: "7f6fed4bb83f4e3a9d5408e3afa00558" member_type: VOTER last_known_addr { host: "127.1.99.129" port: 34103 } }
I20260812 06:18:19.245445  2008 raft_consensus.cc:399] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:19.245471  2008 raft_consensus.cc:493] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:19.245505  2008 raft_consensus.cc:3060] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:19.246194  2008 raft_consensus.cc:515] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7f6fed4bb83f4e3a9d5408e3afa00558" member_type: VOTER last_known_addr { host: "127.1.99.129" port: 34103 } }
I20260812 06:18:19.246322  2008 leader_election.cc:304] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558 [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: 7f6fed4bb83f4e3a9d5408e3afa00558; no voters: 
I20260812 06:18:19.246492  2008 leader_election.cc:290] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:19.246637  2010 raft_consensus.cc:2804] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:19.246851  1985 heartbeater.cc:499] Master 127.1.99.190:33407 was elected leader, sending a full tablet report...
I20260812 06:18:19.246912  2010 raft_consensus.cc:697] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558 [term 1 LEADER]: Becoming Leader. State: Replica: 7f6fed4bb83f4e3a9d5408e3afa00558, State: Running, Role: LEADER
I20260812 06:18:19.247085  2010 consensus_queue.cc:237] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558 [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: "7f6fed4bb83f4e3a9d5408e3afa00558" member_type: VOTER last_known_addr { host: "127.1.99.129" port: 34103 } }
I20260812 06:18:19.247157  2008 ts_tablet_manager.cc:1434] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:18:19.248518  1775 catalog_manager.cc:5719] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558 reported cstate change: term changed from 0 to 1, leader changed from <none> to 7f6fed4bb83f4e3a9d5408e3afa00558 (127.1.99.129). New cstate: current_term: 1 leader_uuid: "7f6fed4bb83f4e3a9d5408e3afa00558" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7f6fed4bb83f4e3a9d5408e3afa00558" member_type: VOTER last_known_addr { host: "127.1.99.129" port: 34103 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:19.310021  1422 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.019s	sys 0.004s
I20260812 06:18:19.463044  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushMRSOp(90ca010d615d4b8998e9aef192da5042): perf score=19.054940
I20260812 06:18:19.630481  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushMRSOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.167s	user 0.127s	sys 0.036s Metrics: {"bytes_written":12676799,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":98,"dirs.run_cpu_time_us":268,"dirs.run_wall_time_us":945,"drs_written":1,"lbm_read_time_us":79,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40809,"lbm_writes_lt_1ms":766,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":8448,"update_count":1545}
I20260812 06:18:19.631146  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling LogGCOp(90ca010d615d4b8998e9aef192da5042): free 20743880 bytes of WAL
I20260812 06:18:19.631433  1891 log_reader.cc:385] T 90ca010d615d4b8998e9aef192da5042: removed 2 log segments from log reader
I20260812 06:18:19.631481  1891 log.cc:1079] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/90ca010d615d4b8998e9aef192da5042/wal-000000001 (ops 1-6)
I20260812 06:18:19.631513  1891 log.cc:1079] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/90ca010d615d4b8998e9aef192da5042/wal-000000002 (ops 7-11)
I20260812 06:18:19.636397  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: LogGCOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:19.636755  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=2.188937
I20260812 06:18:19.657164  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.020s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4143687,"delete_count":0,"lbm_write_time_us":4381,"lbm_writes_lt_1ms":104,"reinsert_count":0,"update_count":505}
I20260812 06:18:19.657608  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling UndoDeltaBlockGCOp(90ca010d615d4b8998e9aef192da5042): 16411392 bytes on disk
I20260812 06:18:19.658094  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: UndoDeltaBlockGCOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:18:19.658514  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=2.188937
I20260812 06:18:19.672365  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5286,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:19.672880  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling MajorDeltaCompactionOp(90ca010d615d4b8998e9aef192da5042): perf score=1.000000
I20260812 06:18:19.873423  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: MajorDeltaCompactionOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.200s	user 0.124s	sys 0.072s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774891,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":74,"lbm_read_time_us":13983,"lbm_reads_lt_1ms":569,"lbm_write_time_us":34871,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"thread_start_us":260,"threads_started":5,"update_count":2500}
I20260812 06:18:19.874049  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=14.095187
I20260812 06:18:19.937018  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.063s	user 0.030s	sys 0.031s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23119,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:19.937649  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=2.188937
I20260812 06:18:19.949378  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4602,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.949890  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling MajorDeltaCompactionOp(90ca010d615d4b8998e9aef192da5042): perf score=1.000000
I20260812 06:18:20.138890  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: MajorDeltaCompactionOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.189s	user 0.140s	sys 0.048s 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":829,"lbm_read_time_us":15322,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29540,"lbm_writes_lt_1ms":543,"mutex_wait_us":384,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7552,"update_count":2500}
I20260812 06:18:20.139506  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=14.095187
I20260812 06:18:20.203156  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.063s	user 0.036s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20437,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:20.203753  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=2.188937
I20260812 06:18:20.214871  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4403,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:20.215353  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling MajorDeltaCompactionOp(90ca010d615d4b8998e9aef192da5042): perf score=1.000000
I20260812 06:18:20.413964  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: MajorDeltaCompactionOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.198s	user 0.124s	sys 0.065s 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":603,"lbm_read_time_us":13224,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33399,"lbm_writes_lt_1ms":543,"mutex_wait_us":46,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:18:20.414584  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=14.095187
I20260812 06:18:20.466205  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.051s	user 0.024s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19719,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:20.466776  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=2.188937
I20260812 06:18:20.478619  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4392,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:20.479214  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling MajorDeltaCompactionOp(90ca010d615d4b8998e9aef192da5042): perf score=1.000000
I20260812 06:18:20.690467  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: MajorDeltaCompactionOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.211s	user 0.121s	sys 0.078s 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":195,"lbm_read_time_us":13854,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32766,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10240,"update_count":2500}
I20260812 06:18:20.691335  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=14.095187
I20260812 06:18:20.740686  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.049s	user 0.023s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22832,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:20.741238  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=2.188937
I20260812 06:18:20.753662  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.012s	user 0.000s	sys 0.011s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5012,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:20.754137  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling MajorDeltaCompactionOp(90ca010d615d4b8998e9aef192da5042): perf score=1.000000
I20260812 06:18:20.925267  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: MajorDeltaCompactionOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.171s	user 0.110s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":761,"lbm_read_time_us":11155,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32047,"lbm_writes_lt_1ms":543,"mutex_wait_us":48,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":45568,"update_count":2500}
I20260812 06:18:20.926003  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=14.095187
I20260812 06:18:20.977823  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.052s	user 0.024s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24525,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:20.978413  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=2.188937
I20260812 06:18:20.994962  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.016s	user 0.009s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6286,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:20.995492  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushMRSOp(90ca010d615d4b8998e9aef192da5042): perf score=1.000000
I20260812 06:18:21.024343  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushMRSOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.029s	user 0.022s	sys 0.005s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":274,"dirs.run_wall_time_us":1316,"drs_written":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1982,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:21.024969  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling LogGCOp(90ca010d615d4b8998e9aef192da5042): free 124710293 bytes of WAL
I20260812 06:18:21.025207  1891 log_reader.cc:385] T 90ca010d615d4b8998e9aef192da5042: removed 12 log segments from log reader
I20260812 06:18:21.025270  1891 log.cc:1079] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/90ca010d615d4b8998e9aef192da5042/wal-000000003 (ops 12-16)
I20260812 06:18:21.025323  1891 log.cc:1079] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/90ca010d615d4b8998e9aef192da5042/wal-000000004 (ops 17-21)
I20260812 06:18:21.025381  1891 log.cc:1079] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/90ca010d615d4b8998e9aef192da5042/wal-000000005 (ops 22-26)
I20260812 06:18:21.025421  1891 log.cc:1079] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/90ca010d615d4b8998e9aef192da5042/wal-000000006 (ops 27-31)
I20260812 06:18:21.025460  1891 log.cc:1079] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/90ca010d615d4b8998e9aef192da5042/wal-000000007 (ops 32-36)
I20260812 06:18:21.025499  1891 log.cc:1079] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/90ca010d615d4b8998e9aef192da5042/wal-000000008 (ops 37-41)
I20260812 06:18:21.025540  1891 log.cc:1079] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/90ca010d615d4b8998e9aef192da5042/wal-000000009 (ops 42-46)
I20260812 06:18:21.025578  1891 log.cc:1079] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/90ca010d615d4b8998e9aef192da5042/wal-000000010 (ops 47-51)
I20260812 06:18:21.025617  1891 log.cc:1079] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/90ca010d615d4b8998e9aef192da5042/wal-000000011 (ops 52-56)
I20260812 06:18:21.025656  1891 log.cc:1079] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/90ca010d615d4b8998e9aef192da5042/wal-000000012 (ops 57-61)
I20260812 06:18:21.025694  1891 log.cc:1079] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/90ca010d615d4b8998e9aef192da5042/wal-000000013 (ops 62-66)
I20260812 06:18:21.025732  1891 log.cc:1079] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/90ca010d615d4b8998e9aef192da5042/wal-000000014 (ops 67-71)
I20260812 06:18:21.056046  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: LogGCOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:18:21.056917  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling UndoDeltaBlockGCOp(90ca010d615d4b8998e9aef192da5042): 473 bytes on disk
I20260812 06:18:21.057422  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: UndoDeltaBlockGCOp(90ca010d615d4b8998e9aef192da5042) 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:18:21.057935  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=5.165500
I20260812 06:18:21.086304  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.028s	user 0.011s	sys 0.014s Metrics: {"bytes_written":6728209,"delete_count":0,"lbm_write_time_us":6764,"lbm_writes_lt_1ms":167,"reinsert_count":0,"update_count":820}
I20260812 06:18:21.087057  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=1.000000
I20260812 06:18:21.098423  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":1477052,"delete_count":0,"lbm_write_time_us":4429,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":38,"reinsert_count":0,"update_count":180}
I20260812 06:18:21.098966  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling MajorDeltaCompactionOp(90ca010d615d4b8998e9aef192da5042): perf score=1.000000
I20260812 06:18:21.360343  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: MajorDeltaCompactionOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.261s	user 0.166s	sys 0.092s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":495,"lbm_read_time_us":16741,"lbm_reads_lt_1ms":774,"lbm_write_time_us":42991,"lbm_writes_lt_1ms":743,"mutex_wait_us":38,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":13312,"thread_start_us":103,"threads_started":1,"update_count":3500}
I20260812 06:18:21.361210  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=18.063937
I20260812 06:18:21.414945  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.053s	user 0.040s	sys 0.011s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":22886,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:21.415625  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=2.188937
I20260812 06:18:21.428480  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4506,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:21.429023  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling MajorDeltaCompactionOp(90ca010d615d4b8998e9aef192da5042): perf score=1.000000
I20260812 06:18:21.660419  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: MajorDeltaCompactionOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.231s	user 0.139s	sys 0.091s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":773,"lbm_read_time_us":15850,"lbm_reads_lt_1ms":672,"lbm_write_time_us":39767,"lbm_writes_lt_1ms":643,"mutex_wait_us":29,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":44544,"update_count":3000}
I20260812 06:18:21.661203  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=14.095187
I20260812 06:18:21.724407  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.063s	user 0.021s	sys 0.040s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":28061,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:21.724974  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=2.188937
I20260812 06:18:21.739888  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5585,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:21.740365  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling MajorDeltaCompactionOp(90ca010d615d4b8998e9aef192da5042): perf score=1.000000
I20260812 06:18:21.910271  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: MajorDeltaCompactionOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.170s	user 0.110s	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":156,"lbm_read_time_us":11525,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29603,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2500}
I20260812 06:18:21.910887  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=15.087375
I20260812 06:18:21.959352  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.048s	user 0.035s	sys 0.012s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":21664,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:21.960201  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=2.188937
I20260812 06:18:21.979261  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.019s	user 0.015s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5977,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:21.979791  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling MajorDeltaCompactionOp(90ca010d615d4b8998e9aef192da5042): perf score=1.000000
I20260812 06:18:22.165583  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: MajorDeltaCompactionOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.186s	user 0.122s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774675,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":699,"lbm_read_time_us":12849,"lbm_reads_lt_1ms":564,"lbm_write_time_us":32785,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:22.166405  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=14.095187
I20260812 06:18:22.228677  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.062s	user 0.024s	sys 0.035s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":22965,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:22.229382  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=2.188937
I20260812 06:18:22.243827  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.014s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4339,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.244378  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling MajorDeltaCompactionOp(90ca010d615d4b8998e9aef192da5042): perf score=1.000000
I20260812 06:18:22.443797  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: MajorDeltaCompactionOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.199s	user 0.137s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774692,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":779,"lbm_read_time_us":14630,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32309,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9216,"update_count":2500}
I20260812 06:18:22.444483  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=14.095187
I20260812 06:18:22.508339  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.064s	user 0.036s	sys 0.017s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":19074,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:22.508998  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=2.188937
I20260812 06:18:22.520776  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4465,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.521306  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushMRSOp(90ca010d615d4b8998e9aef192da5042): perf score=1.000000
I20260812 06:18:22.568399  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushMRSOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.047s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":199,"dirs.run_wall_time_us":1254,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2120,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:22.569161  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling LogGCOp(90ca010d615d4b8998e9aef192da5042): free 112239270 bytes of WAL
I20260812 06:18:22.569425  1891 log_reader.cc:385] T 90ca010d615d4b8998e9aef192da5042: removed 11 log segments from log reader
I20260812 06:18:22.569490  1891 log.cc:1079] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/90ca010d615d4b8998e9aef192da5042/wal-000000015 (ops 72-76)
I20260812 06:18:22.569545  1891 log.cc:1079] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/90ca010d615d4b8998e9aef192da5042/wal-000000016 (ops 77-80)
I20260812 06:18:22.569602  1891 log.cc:1079] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/90ca010d615d4b8998e9aef192da5042/wal-000000017 (ops 81-85)
I20260812 06:18:22.569648  1891 log.cc:1079] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/90ca010d615d4b8998e9aef192da5042/wal-000000018 (ops 86-90)
I20260812 06:18:22.569686  1891 log.cc:1079] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/90ca010d615d4b8998e9aef192da5042/wal-000000019 (ops 91-95)
I20260812 06:18:22.569727  1891 log.cc:1079] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/90ca010d615d4b8998e9aef192da5042/wal-000000020 (ops 96-100)
I20260812 06:18:22.569767  1891 log.cc:1079] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/90ca010d615d4b8998e9aef192da5042/wal-000000021 (ops 101-105)
I20260812 06:18:22.569809  1891 log.cc:1079] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/90ca010d615d4b8998e9aef192da5042/wal-000000022 (ops 106-110)
I20260812 06:18:22.569849  1891 log.cc:1079] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/90ca010d615d4b8998e9aef192da5042/wal-000000023 (ops 111-115)
I20260812 06:18:22.569888  1891 log.cc:1079] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/90ca010d615d4b8998e9aef192da5042/wal-000000024 (ops 116-120)
I20260812 06:18:22.569928  1891 log.cc:1079] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/90ca010d615d4b8998e9aef192da5042/wal-000000025 (ops 121-125)
I20260812 06:18:22.596207  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: LogGCOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.027s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:22.596724  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=2.188937
I20260812 06:18:22.613904  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.017s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5216,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.614414  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=2.188937
I20260812 06:18:22.625671  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4272,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.626289  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling MajorDeltaCompactionOp(90ca010d615d4b8998e9aef192da5042): perf score=1.000000
I20260812 06:18:22.877005  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: MajorDeltaCompactionOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.250s	user 0.162s	sys 0.082s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979752,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":676,"dirs.run_cpu_time_us":549,"dirs.run_wall_time_us":4096,"lbm_read_time_us":15075,"lbm_reads_lt_1ms":774,"lbm_write_time_us":42418,"lbm_writes_lt_1ms":743,"mutex_wait_us":358,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":3500}
I20260812 06:18:22.877665  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling UndoDeltaBlockGCOp(90ca010d615d4b8998e9aef192da5042): 447 bytes on disk
I20260812 06:18:22.878122  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: UndoDeltaBlockGCOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:18:22.878645  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=14.095187
I20260812 06:18:22.927155  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.048s	user 0.045s	sys 0.001s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20237,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:22.927862  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=2.188937
I20260812 06:18:22.945452  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.017s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6702,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.946408  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling MajorDeltaCompactionOp(90ca010d615d4b8998e9aef192da5042): perf score=1.000000
I20260812 06:18:23.135294  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: MajorDeltaCompactionOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.188s	user 0.112s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":164,"lbm_read_time_us":12464,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31136,"lbm_writes_lt_1ms":543,"mutex_wait_us":73,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:18:23.136099  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=14.095187
I20260812 06:18:23.196609  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.060s	user 0.039s	sys 0.016s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":24779,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:23.197317  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=2.188937
I20260812 06:18:23.210258  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.013s	user 0.000s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5110,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:23.211077  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling MajorDeltaCompactionOp(90ca010d615d4b8998e9aef192da5042): perf score=1.000000
I20260812 06:18:23.394820  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: MajorDeltaCompactionOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.183s	user 0.121s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":163,"lbm_read_time_us":12462,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32595,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9856,"update_count":2500}
I20260812 06:18:23.395610  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=14.095187
I20260812 06:18:23.461035  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.065s	user 0.035s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23551,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:23.461815  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=2.188937
I20260812 06:18:23.473024  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4269,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:23.473699  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling MajorDeltaCompactionOp(90ca010d615d4b8998e9aef192da5042): perf score=1.000000
I20260812 06:18:23.663127  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: MajorDeltaCompactionOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.189s	user 0.134s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":389,"lbm_read_time_us":13924,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33809,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2500}
I20260812 06:18:23.664027  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=10.126437
I20260812 06:18:23.702620  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.038s	user 0.024s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16916,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:23.703290  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=2.188937
I20260812 06:18:23.715027  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.012s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4237,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:23.715529  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling MajorDeltaCompactionOp(90ca010d615d4b8998e9aef192da5042): perf score=1.000000
I20260812 06:18:23.853384  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: MajorDeltaCompactionOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.138s	user 0.113s	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":572,"lbm_read_time_us":9176,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25560,"lbm_writes_lt_1ms":443,"mutex_wait_us":68,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2000}
I20260812 06:18:23.853964  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=10.126437
I20260812 06:18:23.895359  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.041s	user 0.025s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15759,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:23.895967  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=2.188937
I20260812 06:18:23.906973  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4084,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:23.907680  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling MajorDeltaCompactionOp(90ca010d615d4b8998e9aef192da5042): perf score=1.000000
I20260812 06:18:24.037750  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: MajorDeltaCompactionOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.130s	user 0.102s	sys 0.028s 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":725,"lbm_read_time_us":8170,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27437,"lbm_writes_lt_1ms":443,"mutex_wait_us":50,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":89216,"update_count":2000}
I20260812 06:18:24.038496  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=10.126437
I20260812 06:18:24.089314  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.051s	user 0.020s	sys 0.016s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16861,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:24.089936  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=2.188937
I20260812 06:18:24.106593  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.016s	user 0.000s	sys 0.014s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6353,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.108841  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushMRSOp(90ca010d615d4b8998e9aef192da5042): perf score=1.000000
I20260812 06:18:24.148167  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushMRSOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.037s	user 0.030s	sys 0.005s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":53,"dirs.run_cpu_time_us":241,"dirs.run_wall_time_us":1345,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1907,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:24.148981  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling LogGCOp(90ca010d615d4b8998e9aef192da5042): free 121006736 bytes of WAL
I20260812 06:18:24.149266  1891 log_reader.cc:385] T 90ca010d615d4b8998e9aef192da5042: removed 12 log segments from log reader
I20260812 06:18:24.149341  1891 log.cc:1079] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/90ca010d615d4b8998e9aef192da5042/wal-000000026 (ops 126-130)
I20260812 06:18:24.149381  1891 log.cc:1079] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/90ca010d615d4b8998e9aef192da5042/wal-000000027 (ops 131-135)
I20260812 06:18:24.149411  1891 log.cc:1079] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/90ca010d615d4b8998e9aef192da5042/wal-000000028 (ops 136-140)
I20260812 06:18:24.149436  1891 log.cc:1079] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/90ca010d615d4b8998e9aef192da5042/wal-000000029 (ops 141-145)
I20260812 06:18:24.149471  1891 log.cc:1079] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/90ca010d615d4b8998e9aef192da5042/wal-000000030 (ops 146-150)
I20260812 06:18:24.149506  1891 log.cc:1079] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/90ca010d615d4b8998e9aef192da5042/wal-000000031 (ops 151-154)
I20260812 06:18:24.149529  1891 log.cc:1079] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/90ca010d615d4b8998e9aef192da5042/wal-000000032 (ops 155-159)
I20260812 06:18:24.149559  1891 log.cc:1079] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/90ca010d615d4b8998e9aef192da5042/wal-000000033 (ops 160-164)
I20260812 06:18:24.149587  1891 log.cc:1079] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/90ca010d615d4b8998e9aef192da5042/wal-000000034 (ops 165-169)
I20260812 06:18:24.149621  1891 log.cc:1079] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/90ca010d615d4b8998e9aef192da5042/wal-000000035 (ops 170-174)
I20260812 06:18:24.149654  1891 log.cc:1079] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/90ca010d615d4b8998e9aef192da5042/wal-000000036 (ops 175-179)
I20260812 06:18:24.149685  1891 log.cc:1079] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: Deleting log segment in path: /tmp/dist-test-taskUnVCmy/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515493390011-1422-0/minicluster-data/ts-0-root/wals/90ca010d615d4b8998e9aef192da5042/wal-000000037 (ops 180-184)
I20260812 06:18:24.182483  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: LogGCOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.033s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:18:24.182933  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=2.188937
I20260812 06:18:24.205204  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.022s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5938,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.205760  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=2.188937
I20260812 06:18:24.217272  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4523,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.218138  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling UndoDeltaBlockGCOp(90ca010d615d4b8998e9aef192da5042): 463 bytes on disk
I20260812 06:18:24.218992  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: UndoDeltaBlockGCOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":145,"lbm_reads_lt_1ms":4}
I20260812 06:18:24.219615  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling MajorDeltaCompactionOp(90ca010d615d4b8998e9aef192da5042): perf score=1.000000
I20260812 06:18:24.398954  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: MajorDeltaCompactionOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.179s	user 0.141s	sys 0.035s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877340,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1159,"lbm_read_time_us":13347,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34853,"lbm_writes_lt_1ms":643,"mutex_wait_us":827,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2048,"thread_start_us":116,"threads_started":1,"update_count":3000}
I20260812 06:18:24.399844  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=14.095187
I20260812 06:18:24.453132  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.053s	user 0.031s	sys 0.019s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24382,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:24.453697  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=2.188937
I20260812 06:18:24.467320  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4733,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.467859  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling MajorDeltaCompactionOp(90ca010d615d4b8998e9aef192da5042): perf score=1.000000
I20260812 06:18:24.539852  1422 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.230s	user 1.870s	sys 0.219s
I20260812 06:18:24.602422  1422 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.062s	user 0.001s	sys 0.000s
I20260812 06:18:24.603101  1422 tablet_server.cc:179] TabletServer@127.1.99.129:0 shutting down...
I20260812 06:18:24.617794  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: MajorDeltaCompactionOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.150s	user 0.105s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1468,"lbm_read_time_us":11591,"lbm_reads_lt_1ms":568,"lbm_write_time_us":27922,"lbm_writes_lt_1ms":543,"mutex_wait_us":661,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17536,"update_count":2500}
I20260812 06:18:24.618635  1986 maintenance_manager.cc:419] P 7f6fed4bb83f4e3a9d5408e3afa00558: Scheduling FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042): perf score=6.157687
I20260812 06:18:24.641093  1891 maintenance_manager.cc:643] P 7f6fed4bb83f4e3a9d5408e3afa00558: FlushDeltaMemStoresOp(90ca010d615d4b8998e9aef192da5042) complete. Timing: real 0.022s	user 0.004s	sys 0.016s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9849,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:24.641800  1422 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:24.642081  1422 tablet_replica.cc:333] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558: stopping tablet replica
I20260812 06:18:24.642252  1422 raft_consensus.cc:2243] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:24.642480  1422 raft_consensus.cc:2272] T 90ca010d615d4b8998e9aef192da5042 P 7f6fed4bb83f4e3a9d5408e3afa00558 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:24.646123  1422 tablet_server.cc:196] TabletServer@127.1.99.129:0 shutdown complete.
I20260812 06:18:24.662778  1422 master.cc:562] Master@127.1.99.190:33407 shutting down...
I20260812 06:18:24.666970  1422 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 9cd201b671ec496e8ee70804960e234e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:24.667162  1422 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 9cd201b671ec496e8ee70804960e234e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:24.667213  1422 tablet_replica.cc:333] T 00000000000000000000000000000000 P 9cd201b671ec496e8ee70804960e234e: stopping tablet replica
I20260812 06:18:24.679749  1422 master.cc:584] Master@127.1.99.190:33407 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5690 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11376 ms total)

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