[==========] 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:27.610101 24581 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.24.1.126:35227
I20260812 06:18:27.611079 24581 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:27.611681 24581 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:27.618466 24594 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:27.618508 24591 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:27.618618 24581 server_base.cc:1061] running on GCE node
W20260812 06:18:27.618875 24590 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:27.619402 24581 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:27.619534 24581 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:27.619599 24581 hybrid_clock.cc:648] HybridClock initialized: now 1786515507619597 us; error 0 us; skew 500 ppm
I20260812 06:18:27.621433 24581 webserver.cc:533] Webserver started at http://127.24.1.126:35093/ using document root <none> and password file <none>
I20260812 06:18:27.621976 24581 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:27.622068 24581 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:27.622344 24581 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:27.624012 24581 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/master-0-root/instance:
uuid: "7b4f5f1b487b40dd8fd3170ef291e144"
format_stamp: "Formatted at 2026-08-12 06:18:27 on dist-test-slave-g170"
I20260812 06:18:27.627807 24581 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.006s	sys 0.000s
I20260812 06:18:27.629993 24605 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:27.631026 24581 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:27.631173 24581 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/master-0-root
uuid: "7b4f5f1b487b40dd8fd3170ef291e144"
format_stamp: "Formatted at 2026-08-12 06:18:27 on dist-test-slave-g170"
I20260812 06:18:27.631285 24581 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-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:27.651007 24581 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:27.651648 24581 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:27.651844 24581 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:27.660041 24581 rpc_server.cc:307] RPC server started. Bound to: 127.24.1.126:35227
I20260812 06:18:27.660064 24705 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.1.126:35227 every 8 connection(s)
I20260812 06:18:27.662338 24706 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:27.667696 24706 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 7b4f5f1b487b40dd8fd3170ef291e144: Bootstrap starting.
I20260812 06:18:27.670181 24706 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 7b4f5f1b487b40dd8fd3170ef291e144: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:27.671049 24706 log.cc:826] T 00000000000000000000000000000000 P 7b4f5f1b487b40dd8fd3170ef291e144: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:27.672729 24706 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 7b4f5f1b487b40dd8fd3170ef291e144: No bootstrap required, opened a new log
I20260812 06:18:27.675477 24706 raft_consensus.cc:359] T 00000000000000000000000000000000 P 7b4f5f1b487b40dd8fd3170ef291e144 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7b4f5f1b487b40dd8fd3170ef291e144" member_type: VOTER }
I20260812 06:18:27.675637 24706 raft_consensus.cc:385] T 00000000000000000000000000000000 P 7b4f5f1b487b40dd8fd3170ef291e144 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:27.675688 24706 raft_consensus.cc:740] T 00000000000000000000000000000000 P 7b4f5f1b487b40dd8fd3170ef291e144 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 7b4f5f1b487b40dd8fd3170ef291e144, State: Initialized, Role: FOLLOWER
I20260812 06:18:27.676287 24706 consensus_queue.cc:260] T 00000000000000000000000000000000 P 7b4f5f1b487b40dd8fd3170ef291e144 [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: "7b4f5f1b487b40dd8fd3170ef291e144" member_type: VOTER }
I20260812 06:18:27.676430 24706 raft_consensus.cc:399] T 00000000000000000000000000000000 P 7b4f5f1b487b40dd8fd3170ef291e144 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:27.676481 24706 raft_consensus.cc:493] T 00000000000000000000000000000000 P 7b4f5f1b487b40dd8fd3170ef291e144 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:27.676568 24706 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 7b4f5f1b487b40dd8fd3170ef291e144 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:27.677317 24706 raft_consensus.cc:515] T 00000000000000000000000000000000 P 7b4f5f1b487b40dd8fd3170ef291e144 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7b4f5f1b487b40dd8fd3170ef291e144" member_type: VOTER }
I20260812 06:18:27.677690 24706 leader_election.cc:304] T 00000000000000000000000000000000 P 7b4f5f1b487b40dd8fd3170ef291e144 [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: 7b4f5f1b487b40dd8fd3170ef291e144; no voters: 
I20260812 06:18:27.677960 24706 leader_election.cc:290] T 00000000000000000000000000000000 P 7b4f5f1b487b40dd8fd3170ef291e144 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:27.678126 24712 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 7b4f5f1b487b40dd8fd3170ef291e144 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:27.678442 24712 raft_consensus.cc:697] T 00000000000000000000000000000000 P 7b4f5f1b487b40dd8fd3170ef291e144 [term 1 LEADER]: Becoming Leader. State: Replica: 7b4f5f1b487b40dd8fd3170ef291e144, State: Running, Role: LEADER
I20260812 06:18:27.678898 24712 consensus_queue.cc:237] T 00000000000000000000000000000000 P 7b4f5f1b487b40dd8fd3170ef291e144 [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: "7b4f5f1b487b40dd8fd3170ef291e144" member_type: VOTER }
I20260812 06:18:27.679013 24706 sys_catalog.cc:565] T 00000000000000000000000000000000 P 7b4f5f1b487b40dd8fd3170ef291e144 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:27.680999 24713 sys_catalog.cc:455] T 00000000000000000000000000000000 P 7b4f5f1b487b40dd8fd3170ef291e144 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "7b4f5f1b487b40dd8fd3170ef291e144" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7b4f5f1b487b40dd8fd3170ef291e144" member_type: VOTER } }
I20260812 06:18:27.680969 24714 sys_catalog.cc:455] T 00000000000000000000000000000000 P 7b4f5f1b487b40dd8fd3170ef291e144 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 7b4f5f1b487b40dd8fd3170ef291e144. Latest consensus state: current_term: 1 leader_uuid: "7b4f5f1b487b40dd8fd3170ef291e144" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7b4f5f1b487b40dd8fd3170ef291e144" member_type: VOTER } }
I20260812 06:18:27.681115 24714 sys_catalog.cc:458] T 00000000000000000000000000000000 P 7b4f5f1b487b40dd8fd3170ef291e144 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:27.681115 24713 sys_catalog.cc:458] T 00000000000000000000000000000000 P 7b4f5f1b487b40dd8fd3170ef291e144 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:27.681430 24581 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:18:27.683423 24742 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 7b4f5f1b487b40dd8fd3170ef291e144: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:18:27.683511 24742 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:18:27.683580 24741 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:27.684338 24741 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:27.689414 24741 catalog_manager.cc:1383] Generated new cluster ID: 1effef96946c4506857f23900243d8d8
I20260812 06:18:27.689478 24741 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:27.695094 24741 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:27.696144 24741 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:27.703837 24741 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 7b4f5f1b487b40dd8fd3170ef291e144: Generated new TSK 0
I20260812 06:18:27.704512 24741 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:27.713972 24581 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:27.716840 24754 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:27.716990 24581 server_base.cc:1061] running on GCE node
W20260812 06:18:27.716861 24751 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:27.716814 24750 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:27.717301 24581 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:27.717347 24581 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:27.717362 24581 hybrid_clock.cc:648] HybridClock initialized: now 1786515507717362 us; error 0 us; skew 500 ppm
I20260812 06:18:27.718286 24581 webserver.cc:533] Webserver started at http://127.24.1.65:37339/ using document root <none> and password file <none>
I20260812 06:18:27.718472 24581 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:27.718519 24581 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:27.718616 24581 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:27.719045 24581 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root/instance:
uuid: "3ea62203edc1475e89a619abae38e1b7"
format_stamp: "Formatted at 2026-08-12 06:18:27 on dist-test-slave-g170"
I20260812 06:18:27.720572 24581 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:27.721698 24763 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:27.721947 24581 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:27.722021 24581 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root
uuid: "3ea62203edc1475e89a619abae38e1b7"
format_stamp: "Formatted at 2026-08-12 06:18:27 on dist-test-slave-g170"
I20260812 06:18:27.722108 24581 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-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:27.739001 24581 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:27.739496 24581 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:27.740036 24581 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:27.741011 24581 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:27.741066 24581 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:27.741137 24581 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:27.741175 24581 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:27.748155 24581 rpc_server.cc:307] RPC server started. Bound to: 127.24.1.65:46307
I20260812 06:18:27.748191 24893 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.1.65:46307 every 8 connection(s)
I20260812 06:18:27.759763 24894 heartbeater.cc:344] Connected to a master server at 127.24.1.126:35227
I20260812 06:18:27.760037 24894 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:27.760480 24894 heartbeater.cc:507] Master 127.24.1.126:35227 requested a full tablet report, sending...
I20260812 06:18:27.762136 24634 ts_manager.cc:194] Registered new tserver with Master: 3ea62203edc1475e89a619abae38e1b7 (127.24.1.65:46307)
I20260812 06:18:27.762454 24581 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.0135786s
I20260812 06:18:27.763702 24634 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:42144
I20260812 06:18:27.772251 24634 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:42160:
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:27.787482 24810 tablet_service.cc:1511] Processing CreateTablet for tablet 6c476146e6204eceaa7f2ec5f2169d7f (DEFAULT_TABLE table=heavy-update-compaction-test [id=9f50df47ff7446119579c4ce5a1bf7a8]), partition=
I20260812 06:18:27.788110 24810 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 6c476146e6204eceaa7f2ec5f2169d7f. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:27.790870 24913 tablet_bootstrap.cc:492] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Bootstrap starting.
I20260812 06:18:27.791929 24913 tablet_bootstrap.cc:654] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:27.793265 24913 tablet_bootstrap.cc:492] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: No bootstrap required, opened a new log
I20260812 06:18:27.793411 24913 ts_tablet_manager.cc:1403] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:27.793902 24913 raft_consensus.cc:359] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3ea62203edc1475e89a619abae38e1b7" member_type: VOTER last_known_addr { host: "127.24.1.65" port: 46307 } }
I20260812 06:18:27.794040 24913 raft_consensus.cc:385] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:27.794106 24913 raft_consensus.cc:740] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 3ea62203edc1475e89a619abae38e1b7, State: Initialized, Role: FOLLOWER
I20260812 06:18:27.794274 24913 consensus_queue.cc:260] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7 [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: "3ea62203edc1475e89a619abae38e1b7" member_type: VOTER last_known_addr { host: "127.24.1.65" port: 46307 } }
I20260812 06:18:27.794387 24913 raft_consensus.cc:399] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:27.794437 24913 raft_consensus.cc:493] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:27.794488 24913 raft_consensus.cc:3060] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:27.795436 24913 raft_consensus.cc:515] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3ea62203edc1475e89a619abae38e1b7" member_type: VOTER last_known_addr { host: "127.24.1.65" port: 46307 } }
I20260812 06:18:27.795595 24913 leader_election.cc:304] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7 [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: 3ea62203edc1475e89a619abae38e1b7; no voters: 
I20260812 06:18:27.795845 24913 leader_election.cc:290] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:27.796160 24917 raft_consensus.cc:2804] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:27.796236 24913 ts_tablet_manager.cc:1434] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:27.796463 24894 heartbeater.cc:499] Master 127.24.1.126:35227 was elected leader, sending a full tablet report...
I20260812 06:18:27.796461 24917 raft_consensus.cc:697] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7 [term 1 LEADER]: Becoming Leader. State: Replica: 3ea62203edc1475e89a619abae38e1b7, State: Running, Role: LEADER
I20260812 06:18:27.796669 24917 consensus_queue.cc:237] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7 [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: "3ea62203edc1475e89a619abae38e1b7" member_type: VOTER last_known_addr { host: "127.24.1.65" port: 46307 } }
I20260812 06:18:27.799464 24634 catalog_manager.cc:5719] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7 reported cstate change: term changed from 0 to 1, leader changed from <none> to 3ea62203edc1475e89a619abae38e1b7 (127.24.1.65). New cstate: current_term: 1 leader_uuid: "3ea62203edc1475e89a619abae38e1b7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3ea62203edc1475e89a619abae38e1b7" member_type: VOTER last_known_addr { host: "127.24.1.65" port: 46307 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:27.873518 24581 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.066s	user 0.021s	sys 0.011s
I20260812 06:18:27.999512 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushMRSOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=15.086190
I20260812 06:18:28.179240 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushMRSOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.179s	user 0.140s	sys 0.029s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":741,"delete_count":0,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":223,"dirs.run_wall_time_us":830,"drs_written":1,"lbm_read_time_us":83,"lbm_reads_lt_1ms":4,"lbm_write_time_us":46869,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":656,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"thread_start_us":167,"threads_started":1,"update_count":1500}
I20260812 06:18:28.180548 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling LogGCOp(6c476146e6204eceaa7f2ec5f2169d7f): free 11976772 bytes of WAL
I20260812 06:18:28.180933 24770 log_reader.cc:385] T 6c476146e6204eceaa7f2ec5f2169d7f: removed 1 log segments from log reader
I20260812 06:18:28.181012 24770 log.cc:1079] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/6c476146e6204eceaa7f2ec5f2169d7f/wal-000000001 (ops 1-6)
I20260812 06:18:28.184720 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: LogGCOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.004s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:28.185127 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=2.188937
I20260812 06:18:28.205914 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.021s	user 0.017s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7208,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.206418 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=1.000000
I20260812 06:18:28.355912 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.149s	user 0.114s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":845,"lbm_read_time_us":10828,"lbm_reads_lt_1ms":468,"lbm_write_time_us":28986,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2432,"thread_start_us":375,"threads_started":5,"update_count":2000}
I20260812 06:18:28.356585 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=10.126437
I20260812 06:18:28.399525 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.043s	user 0.019s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15279,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:28.400063 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling UndoDeltaBlockGCOp(6c476146e6204eceaa7f2ec5f2169d7f): 12308959 bytes on disk
I20260812 06:18:28.400604 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: UndoDeltaBlockGCOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:18:28.401108 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=2.188937
I20260812 06:18:28.413636 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.012s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4622,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.414228 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=1.000000
I20260812 06:18:28.548020 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.134s	user 0.109s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":262,"lbm_read_time_us":10692,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25520,"lbm_writes_lt_1ms":443,"mutex_wait_us":327,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:18:28.548503 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=10.126437
I20260812 06:18:28.596566 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.048s	user 0.024s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17326,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:28.597090 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=2.188937
I20260812 06:18:28.607491 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3969,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.608055 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=1.000000
I20260812 06:18:28.731676 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.123s	user 0.083s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":953,"lbm_read_time_us":10509,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23111,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2000}
I20260812 06:18:28.732367 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=10.126437
I20260812 06:18:28.782511 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.050s	user 0.024s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15641,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:28.783118 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=2.188937
I20260812 06:18:28.793821 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4096,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.794278 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=1.000000
I20260812 06:18:28.951634 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.157s	user 0.123s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1797,"lbm_read_time_us":11668,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25413,"lbm_writes_lt_1ms":443,"mutex_wait_us":408,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":2000}
I20260812 06:18:28.952291 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=10.126437
I20260812 06:18:29.000507 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.048s	user 0.030s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17339,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:29.001000 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=2.188937
I20260812 06:18:29.012145 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4082,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.012950 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=1.000000
I20260812 06:18:29.143321 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.130s	user 0.099s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":708,"lbm_read_time_us":9876,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26071,"lbm_writes_lt_1ms":443,"mutex_wait_us":116,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17792,"update_count":2000}
I20260812 06:18:29.143919 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=10.126437
I20260812 06:18:29.182476 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.038s	user 0.020s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15345,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:29.182996 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=2.188937
I20260812 06:18:29.193341 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4002,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.193739 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=1.000000
I20260812 06:18:29.322319 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.128s	user 0.106s	sys 0.021s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":227,"lbm_read_time_us":9679,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26094,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:29.322829 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=10.126437
I20260812 06:18:29.380280 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.057s	user 0.020s	sys 0.021s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":16393,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:29.380849 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=2.188937
I20260812 06:18:29.391428 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4071,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.391934 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushMRSOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=1.000000
I20260812 06:18:29.425262 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushMRSOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.033s	user 0.027s	sys 0.004s Metrics: {"bytes_written":1152509,"cfile_init":1,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":261,"dirs.run_wall_time_us":1354,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1424,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:29.426168 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling UndoDeltaBlockGCOp(6c476146e6204eceaa7f2ec5f2169d7f): 448 bytes on disk
I20260812 06:18:29.426671 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: UndoDeltaBlockGCOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:18:29.427263 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=1.000000
I20260812 06:18:29.592939 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.165s	user 0.121s	sys 0.038s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631315,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":321,"lbm_read_time_us":10827,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27992,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":2000}
I20260812 06:18:29.593565 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling LogGCOp(6c476146e6204eceaa7f2ec5f2169d7f): free 121006422 bytes of WAL
I20260812 06:18:29.593803 24770 log_reader.cc:385] T 6c476146e6204eceaa7f2ec5f2169d7f: removed 12 log segments from log reader
I20260812 06:18:29.593864 24770 log.cc:1079] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/6c476146e6204eceaa7f2ec5f2169d7f/wal-000000002 (ops 7-11)
I20260812 06:18:29.593920 24770 log.cc:1079] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/6c476146e6204eceaa7f2ec5f2169d7f/wal-000000003 (ops 12-16)
I20260812 06:18:29.593966 24770 log.cc:1079] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/6c476146e6204eceaa7f2ec5f2169d7f/wal-000000004 (ops 17-21)
I20260812 06:18:29.594012 24770 log.cc:1079] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/6c476146e6204eceaa7f2ec5f2169d7f/wal-000000005 (ops 22-26)
I20260812 06:18:29.594054 24770 log.cc:1079] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/6c476146e6204eceaa7f2ec5f2169d7f/wal-000000006 (ops 27-31)
I20260812 06:18:29.594108 24770 log.cc:1079] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/6c476146e6204eceaa7f2ec5f2169d7f/wal-000000007 (ops 32-36)
I20260812 06:18:29.594179 24770 log.cc:1079] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/6c476146e6204eceaa7f2ec5f2169d7f/wal-000000008 (ops 37-41)
I20260812 06:18:29.594219 24770 log.cc:1079] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/6c476146e6204eceaa7f2ec5f2169d7f/wal-000000009 (ops 42-46)
I20260812 06:18:29.594251 24770 log.cc:1079] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/6c476146e6204eceaa7f2ec5f2169d7f/wal-000000010 (ops 47-50)
I20260812 06:18:29.594296 24770 log.cc:1079] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/6c476146e6204eceaa7f2ec5f2169d7f/wal-000000011 (ops 51-55)
I20260812 06:18:29.594336 24770 log.cc:1079] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/6c476146e6204eceaa7f2ec5f2169d7f/wal-000000012 (ops 56-60)
I20260812 06:18:29.594375 24770 log.cc:1079] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/6c476146e6204eceaa7f2ec5f2169d7f/wal-000000013 (ops 61-65)
I20260812 06:18:29.625927 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: LogGCOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.032s	user 0.006s	sys 0.025s Metrics: {}
I20260812 06:18:29.626332 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=14.095187
I20260812 06:18:29.677767 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.051s	user 0.047s	sys 0.004s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":22057,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:29.678224 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=3.181125
I20260812 06:18:29.707201 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.029s	user 0.011s	sys 0.008s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4715,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:29.707723 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=2.188937
I20260812 06:18:29.717686 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.010s	user 0.000s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3816,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:29.718128 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=1.000000
I20260812 06:18:29.915087 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.197s	user 0.104s	sys 0.090s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836246,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1110,"lbm_read_time_us":14290,"lbm_reads_lt_1ms":673,"lbm_write_time_us":32982,"lbm_writes_lt_1ms":643,"mutex_wait_us":2,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":3000}
I20260812 06:18:29.915674 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=14.095187
I20260812 06:18:29.978634 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.063s	user 0.031s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21160,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:29.979226 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=2.188937
I20260812 06:18:29.991150 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4545,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.991606 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=1.000000
I20260812 06:18:30.182904 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.191s	user 0.118s	sys 0.072s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1011,"lbm_read_time_us":14877,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32738,"lbm_writes_lt_1ms":543,"mutex_wait_us":303,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":2500}
I20260812 06:18:30.183547 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=10.126437
I20260812 06:18:30.217330 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.034s	user 0.029s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14374,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:30.217813 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=2.188937
I20260812 06:18:30.232640 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5478,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.233392 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=1.000000
I20260812 06:18:30.374015 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.140s	user 0.100s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":898,"lbm_read_time_us":10798,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23408,"lbm_writes_lt_1ms":443,"mutex_wait_us":295,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":2000}
I20260812 06:18:30.374547 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=10.126437
I20260812 06:18:30.419497 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.045s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15392,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:30.420008 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=2.188937
I20260812 06:18:30.431890 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4324,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.432542 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=1.000000
I20260812 06:18:30.570670 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.138s	user 0.097s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":148,"lbm_read_time_us":10473,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26631,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:18:30.571221 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=10.126437
I20260812 06:18:30.607156 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.036s	user 0.015s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14630,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:30.607820 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=1.000000
I20260812 06:18:30.729900 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.122s	user 0.099s	sys 0.022s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":325,"lbm_read_time_us":7477,"lbm_reads_lt_1ms":363,"lbm_write_time_us":23463,"lbm_writes_lt_1ms":343,"mutex_wait_us":37,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":13568,"update_count":1500}
I20260812 06:18:30.730589 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=10.126437
I20260812 06:18:30.772590 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.042s	user 0.018s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14943,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:30.773094 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=2.188937
I20260812 06:18:30.784672 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4639,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.785231 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=1.000000
I20260812 06:18:30.916450 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.131s	user 0.114s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":891,"lbm_read_time_us":8523,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26365,"lbm_writes_lt_1ms":443,"mutex_wait_us":356,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2000}
I20260812 06:18:30.917155 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=10.126437
I20260812 06:18:30.965299 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.048s	user 0.025s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17825,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:30.965826 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=2.188937
I20260812 06:18:30.976841 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3997,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.977551 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushMRSOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=1.000000
I20260812 06:18:31.009357 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushMRSOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.031s	user 0.026s	sys 0.004s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":233,"dirs.run_wall_time_us":1112,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1579,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:31.010076 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling LogGCOp(6c476146e6204eceaa7f2ec5f2169d7f): free 124257248 bytes of WAL
I20260812 06:18:31.010334 24770 log_reader.cc:385] T 6c476146e6204eceaa7f2ec5f2169d7f: removed 12 log segments from log reader
I20260812 06:18:31.010382 24770 log.cc:1079] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/6c476146e6204eceaa7f2ec5f2169d7f/wal-000000014 (ops 66-70)
I20260812 06:18:31.010413 24770 log.cc:1079] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/6c476146e6204eceaa7f2ec5f2169d7f/wal-000000015 (ops 71-75)
I20260812 06:18:31.010492 24770 log.cc:1079] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/6c476146e6204eceaa7f2ec5f2169d7f/wal-000000016 (ops 76-80)
I20260812 06:18:31.010524 24770 log.cc:1079] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/6c476146e6204eceaa7f2ec5f2169d7f/wal-000000017 (ops 81-85)
I20260812 06:18:31.010566 24770 log.cc:1079] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/6c476146e6204eceaa7f2ec5f2169d7f/wal-000000018 (ops 86-90)
I20260812 06:18:31.010629 24770 log.cc:1079] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/6c476146e6204eceaa7f2ec5f2169d7f/wal-000000019 (ops 91-95)
I20260812 06:18:31.010682 24770 log.cc:1079] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/6c476146e6204eceaa7f2ec5f2169d7f/wal-000000020 (ops 96-100)
I20260812 06:18:31.010725 24770 log.cc:1079] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/6c476146e6204eceaa7f2ec5f2169d7f/wal-000000021 (ops 101-105)
I20260812 06:18:31.010764 24770 log.cc:1079] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/6c476146e6204eceaa7f2ec5f2169d7f/wal-000000022 (ops 106-110)
I20260812 06:18:31.010804 24770 log.cc:1079] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/6c476146e6204eceaa7f2ec5f2169d7f/wal-000000023 (ops 111-115)
I20260812 06:18:31.010843 24770 log.cc:1079] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/6c476146e6204eceaa7f2ec5f2169d7f/wal-000000024 (ops 116-120)
I20260812 06:18:31.010882 24770 log.cc:1079] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/6c476146e6204eceaa7f2ec5f2169d7f/wal-000000025 (ops 121-124)
I20260812 06:18:31.040660 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: LogGCOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.030s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:18:31.041239 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling UndoDeltaBlockGCOp(6c476146e6204eceaa7f2ec5f2169d7f): 472 bytes on disk
I20260812 06:18:31.041760 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: UndoDeltaBlockGCOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:18:31.042471 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=6.157687
I20260812 06:18:31.067106 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.024s	user 0.018s	sys 0.004s Metrics: {"bytes_written":7671761,"delete_count":0,"lbm_write_time_us":10090,"lbm_writes_lt_1ms":190,"reinsert_count":0,"update_count":935}
I20260812 06:18:31.067672 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=1.000000
I20260812 06:18:31.275069 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.207s	user 0.145s	sys 0.052s Metrics: {"cfile_cache_miss":620,"cfile_cache_miss_bytes":28302938,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":434,"lbm_read_time_us":14757,"lbm_reads_lt_1ms":656,"lbm_write_time_us":41289,"lbm_writes_lt_1ms":630,"peak_mem_usage":73968633,"reinsert_count":0,"spinlock_wait_cycles":2944,"thread_start_us":75,"threads_started":1,"update_count":2935}
I20260812 06:18:31.275704 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=15.087375
I20260812 06:18:31.334144 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.058s	user 0.035s	sys 0.020s Metrics: {"bytes_written":16943222,"delete_count":0,"lbm_write_time_us":26100,"lbm_writes_lt_1ms":416,"reinsert_count":0,"update_count":2065}
I20260812 06:18:31.334647 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=2.188937
I20260812 06:18:31.345800 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4084,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.346333 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=1.000000
I20260812 06:18:31.511950 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.165s	user 0.109s	sys 0.049s Metrics: {"cfile_cache_miss":545,"cfile_cache_miss_bytes":25267043,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":297,"lbm_read_time_us":12703,"lbm_reads_lt_1ms":585,"lbm_write_time_us":34652,"lbm_writes_lt_1ms":556,"mutex_wait_us":59,"peak_mem_usage":64689739,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2565}
I20260812 06:18:31.512681 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=11.118625
I20260812 06:18:31.546137 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.033s	user 0.015s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14511,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:31.547081 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=2.188937
I20260812 06:18:31.564217 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.017s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4806,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:31.564841 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=1.000000
I20260812 06:18:31.703599 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.139s	user 0.103s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1446,"lbm_read_time_us":9401,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26210,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2000}
I20260812 06:18:31.704445 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=11.118625
I20260812 06:18:31.746621 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.042s	user 0.017s	sys 0.023s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18241,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:31.747376 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=2.188937
I20260812 06:18:31.774495 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.027s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5389,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:31.774956 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=2.188937
I20260812 06:18:31.787261 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.012s	user 0.003s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5491,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.787940 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=1.000000
I20260812 06:18:31.958357 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.170s	user 0.115s	sys 0.044s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733834,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":336,"lbm_read_time_us":9783,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31992,"lbm_writes_lt_1ms":543,"mutex_wait_us":57,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":32256,"update_count":2500}
I20260812 06:18:31.959179 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=14.095187
I20260812 06:18:32.008090 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.049s	user 0.028s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21113,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:32.008631 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=1.000000
I20260812 06:18:32.187053 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.178s	user 0.108s	sys 0.063s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631193,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":208,"lbm_read_time_us":10125,"lbm_reads_lt_1ms":467,"lbm_write_time_us":32971,"lbm_writes_lt_1ms":443,"mutex_wait_us":79,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:32.187733 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=14.095187
I20260812 06:18:32.233608 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.046s	user 0.029s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20100,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:32.234148 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=2.188937
I20260812 06:18:32.246814 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4384,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.247411 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=1.000000
I20260812 06:18:32.458077 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.210s	user 0.149s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":312,"lbm_read_time_us":12565,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34192,"lbm_writes_lt_1ms":543,"mutex_wait_us":70,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:32.458796 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=14.095187
I20260812 06:18:32.506587 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.048s	user 0.026s	sys 0.015s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":18782,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:32.507133 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=2.188937
I20260812 06:18:32.519450 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4457,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.519972 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushMRSOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=1.000000
I20260812 06:18:32.556293 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushMRSOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.036s	user 0.034s	sys 0.000s Metrics: {"bytes_written":1234475,"cfile_init":1,"dirs.queue_time_us":87,"dirs.run_cpu_time_us":298,"dirs.run_wall_time_us":1392,"drs_written":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1680,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:32.557183 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling LogGCOp(6c476146e6204eceaa7f2ec5f2169d7f): free 120553626 bytes of WAL
I20260812 06:18:32.557427 24770 log_reader.cc:385] T 6c476146e6204eceaa7f2ec5f2169d7f: removed 12 log segments from log reader
I20260812 06:18:32.557485 24770 log.cc:1079] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/6c476146e6204eceaa7f2ec5f2169d7f/wal-000000026 (ops 125-129)
I20260812 06:18:32.557518 24770 log.cc:1079] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/6c476146e6204eceaa7f2ec5f2169d7f/wal-000000027 (ops 130-134)
I20260812 06:18:32.557582 24770 log.cc:1079] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/6c476146e6204eceaa7f2ec5f2169d7f/wal-000000028 (ops 135-138)
I20260812 06:18:32.557654 24770 log.cc:1079] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/6c476146e6204eceaa7f2ec5f2169d7f/wal-000000029 (ops 139-143)
I20260812 06:18:32.557713 24770 log.cc:1079] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/6c476146e6204eceaa7f2ec5f2169d7f/wal-000000030 (ops 144-148)
I20260812 06:18:32.557734 24770 log.cc:1079] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/6c476146e6204eceaa7f2ec5f2169d7f/wal-000000031 (ops 149-153)
I20260812 06:18:32.557793 24770 log.cc:1079] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/6c476146e6204eceaa7f2ec5f2169d7f/wal-000000032 (ops 154-158)
I20260812 06:18:32.557835 24770 log.cc:1079] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/6c476146e6204eceaa7f2ec5f2169d7f/wal-000000033 (ops 159-163)
I20260812 06:18:32.557878 24770 log.cc:1079] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/6c476146e6204eceaa7f2ec5f2169d7f/wal-000000034 (ops 164-168)
I20260812 06:18:32.557916 24770 log.cc:1079] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/6c476146e6204eceaa7f2ec5f2169d7f/wal-000000035 (ops 169-172)
I20260812 06:18:32.557962 24770 log.cc:1079] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/6c476146e6204eceaa7f2ec5f2169d7f/wal-000000036 (ops 173-177)
I20260812 06:18:32.558005 24770 log.cc:1079] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/6c476146e6204eceaa7f2ec5f2169d7f/wal-000000037 (ops 178-182)
I20260812 06:18:32.593343 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: LogGCOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.036s	user 0.000s	sys 0.035s Metrics: {}
I20260812 06:18:32.593783 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=3.181125
I20260812 06:18:32.621083 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.027s	user 0.008s	sys 0.009s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6507,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:32.621596 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling UndoDeltaBlockGCOp(6c476146e6204eceaa7f2ec5f2169d7f): 473 bytes on disk
I20260812 06:18:32.622023 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: UndoDeltaBlockGCOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:18:32.622571 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=2.188937
I20260812 06:18:32.633286 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4145,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:32.633741 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=1.000000
I20260812 06:18:32.890306 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.256s	user 0.169s	sys 0.084s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938778,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":921,"lbm_read_time_us":18760,"lbm_reads_lt_1ms":774,"lbm_write_time_us":42714,"lbm_writes_lt_1ms":743,"mutex_wait_us":52,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":12288,"thread_start_us":100,"threads_started":1,"update_count":3500}
I20260812 06:18:32.891286 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=15.087375
I20260812 06:18:32.933092 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.042s	user 0.030s	sys 0.011s Metrics: {"bytes_written":16820141,"delete_count":0,"lbm_write_time_us":18484,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:32.933678 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=2.188937
I20260812 06:18:32.949832 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: FlushDeltaMemStoresOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.016s	user 0.010s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5780,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:32.950657 24897 maintenance_manager.cc:419] P 3ea62203edc1475e89a619abae38e1b7: Scheduling MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f): perf score=1.000000
I20260812 06:18:33.014724 24581 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.141s	user 1.872s	sys 0.141s
I20260812 06:18:33.078480 24581 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.063s	user 0.002s	sys 0.000s
I20260812 06:18:33.079110 24581 tablet_server.cc:179] TabletServer@127.24.1.65:0 shutting down...
I20260812 06:18:33.108595 24770 maintenance_manager.cc:643] P 3ea62203edc1475e89a619abae38e1b7: MajorDeltaCompactionOp(6c476146e6204eceaa7f2ec5f2169d7f) complete. Timing: real 0.158s	user 0.116s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733709,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":252,"lbm_read_time_us":10983,"lbm_reads_lt_1ms":560,"lbm_write_time_us":26544,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":21248,"update_count":2500}
I20260812 06:18:33.109437 24581 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:33.109866 24581 tablet_replica.cc:333] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7: stopping tablet replica
I20260812 06:18:33.110141 24581 raft_consensus.cc:2243] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:33.110430 24581 raft_consensus.cc:2272] T 6c476146e6204eceaa7f2ec5f2169d7f P 3ea62203edc1475e89a619abae38e1b7 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:33.128690 24581 tablet_server.cc:196] TabletServer@127.24.1.65:0 shutdown complete.
I20260812 06:18:33.159668 24581 master.cc:562] Master@127.24.1.126:35227 shutting down...
I20260812 06:18:33.163698 24581 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 7b4f5f1b487b40dd8fd3170ef291e144 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:33.163867 24581 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 7b4f5f1b487b40dd8fd3170ef291e144 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:33.163923 24581 tablet_replica.cc:333] T 00000000000000000000000000000000 P 7b4f5f1b487b40dd8fd3170ef291e144: stopping tablet replica
I20260812 06:18:33.176234 24581 master.cc:584] Master@127.24.1.126:35227 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5660 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:33.282130 24581 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.24.1.126:36557
I20260812 06:18:33.282492 24581 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:33.284322 24941 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:33.284426 24940 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:33.284426 24944 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:33.284622 24581 server_base.cc:1061] running on GCE node
I20260812 06:18:33.284904 24581 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:33.284947 24581 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:33.284963 24581 hybrid_clock.cc:648] HybridClock initialized: now 1786515513284964 us; error 0 us; skew 500 ppm
I20260812 06:18:33.285821 24581 webserver.cc:533] Webserver started at http://127.24.1.126:41337/ using document root <none> and password file <none>
I20260812 06:18:33.286008 24581 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:33.286077 24581 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:33.286160 24581 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:33.286592 24581 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/master-0-root/instance:
uuid: "b6c3947b8d704924a496a7e12e256239"
format_stamp: "Formatted at 2026-08-12 06:18:33 on dist-test-slave-g170"
I20260812 06:18:33.288229 24581 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:33.289354 24950 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:33.289851 24581 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.000s
I20260812 06:18:33.289950 24581 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/master-0-root
uuid: "b6c3947b8d704924a496a7e12e256239"
format_stamp: "Formatted at 2026-08-12 06:18:33 on dist-test-slave-g170"
I20260812 06:18:33.290042 24581 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-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:33.300872 24581 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:33.301199 24581 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:33.305763 24581 rpc_server.cc:307] RPC server started. Bound to: 127.24.1.126:36557
I20260812 06:18:33.307277 25047 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.1.126:36557 every 8 connection(s)
I20260812 06:18:33.307926 25048 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:33.313707 25048 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b6c3947b8d704924a496a7e12e256239: Bootstrap starting.
I20260812 06:18:33.314442 25048 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P b6c3947b8d704924a496a7e12e256239: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:33.315416 25048 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b6c3947b8d704924a496a7e12e256239: No bootstrap required, opened a new log
I20260812 06:18:33.315755 25048 raft_consensus.cc:359] T 00000000000000000000000000000000 P b6c3947b8d704924a496a7e12e256239 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b6c3947b8d704924a496a7e12e256239" member_type: VOTER }
I20260812 06:18:33.315835 25048 raft_consensus.cc:385] T 00000000000000000000000000000000 P b6c3947b8d704924a496a7e12e256239 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:33.315857 25048 raft_consensus.cc:740] T 00000000000000000000000000000000 P b6c3947b8d704924a496a7e12e256239 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b6c3947b8d704924a496a7e12e256239, State: Initialized, Role: FOLLOWER
I20260812 06:18:33.315999 25048 consensus_queue.cc:260] T 00000000000000000000000000000000 P b6c3947b8d704924a496a7e12e256239 [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: "b6c3947b8d704924a496a7e12e256239" member_type: VOTER }
I20260812 06:18:33.316092 25048 raft_consensus.cc:399] T 00000000000000000000000000000000 P b6c3947b8d704924a496a7e12e256239 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:33.316118 25048 raft_consensus.cc:493] T 00000000000000000000000000000000 P b6c3947b8d704924a496a7e12e256239 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:33.316152 25048 raft_consensus.cc:3060] T 00000000000000000000000000000000 P b6c3947b8d704924a496a7e12e256239 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:33.316802 25048 raft_consensus.cc:515] T 00000000000000000000000000000000 P b6c3947b8d704924a496a7e12e256239 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b6c3947b8d704924a496a7e12e256239" member_type: VOTER }
I20260812 06:18:33.316910 25048 leader_election.cc:304] T 00000000000000000000000000000000 P b6c3947b8d704924a496a7e12e256239 [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: b6c3947b8d704924a496a7e12e256239; no voters: 
I20260812 06:18:33.317044 25048 leader_election.cc:290] T 00000000000000000000000000000000 P b6c3947b8d704924a496a7e12e256239 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:33.317190 25053 raft_consensus.cc:2804] T 00000000000000000000000000000000 P b6c3947b8d704924a496a7e12e256239 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:33.317427 25053 raft_consensus.cc:697] T 00000000000000000000000000000000 P b6c3947b8d704924a496a7e12e256239 [term 1 LEADER]: Becoming Leader. State: Replica: b6c3947b8d704924a496a7e12e256239, State: Running, Role: LEADER
I20260812 06:18:33.317503 25048 sys_catalog.cc:565] T 00000000000000000000000000000000 P b6c3947b8d704924a496a7e12e256239 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:33.317587 25053 consensus_queue.cc:237] T 00000000000000000000000000000000 P b6c3947b8d704924a496a7e12e256239 [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: "b6c3947b8d704924a496a7e12e256239" member_type: VOTER }
I20260812 06:18:33.318065 25055 sys_catalog.cc:455] T 00000000000000000000000000000000 P b6c3947b8d704924a496a7e12e256239 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "b6c3947b8d704924a496a7e12e256239" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b6c3947b8d704924a496a7e12e256239" member_type: VOTER } }
I20260812 06:18:33.318091 25058 sys_catalog.cc:455] T 00000000000000000000000000000000 P b6c3947b8d704924a496a7e12e256239 [sys.catalog]: SysCatalogTable state changed. Reason: New leader b6c3947b8d704924a496a7e12e256239. Latest consensus state: current_term: 1 leader_uuid: "b6c3947b8d704924a496a7e12e256239" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b6c3947b8d704924a496a7e12e256239" member_type: VOTER } }
I20260812 06:18:33.318167 25055 sys_catalog.cc:458] T 00000000000000000000000000000000 P b6c3947b8d704924a496a7e12e256239 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:33.318179 25058 sys_catalog.cc:458] T 00000000000000000000000000000000 P b6c3947b8d704924a496a7e12e256239 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:33.318451 25062 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:33.319206 25062 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:33.319495 24581 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:33.321157 25062 catalog_manager.cc:1383] Generated new cluster ID: 48e1703d89ba4ef88debe5ddccd5759a
I20260812 06:18:33.321233 25062 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:33.348902 25062 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:33.349561 25062 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:33.360596 25062 catalog_manager.cc:6092] T 00000000000000000000000000000000 P b6c3947b8d704924a496a7e12e256239: Generated new TSK 0
I20260812 06:18:33.360831 25062 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:33.384155 24581 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:33.386242 25081 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:33.386264 25078 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:33.386286 25077 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:33.386714 24581 server_base.cc:1061] running on GCE node
I20260812 06:18:33.386860 24581 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:33.386895 24581 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:33.386910 24581 hybrid_clock.cc:648] HybridClock initialized: now 1786515513386910 us; error 0 us; skew 500 ppm
I20260812 06:18:33.387720 24581 webserver.cc:533] Webserver started at http://127.24.1.65:41103/ using document root <none> and password file <none>
I20260812 06:18:33.387859 24581 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:33.387903 24581 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:33.387962 24581 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:33.388341 24581 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root/instance:
uuid: "766f41ee53c74f3491e95709486d6845"
format_stamp: "Formatted at 2026-08-12 06:18:33 on dist-test-slave-g170"
I20260812 06:18:33.389922 24581 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:33.390841 25087 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:33.391146 24581 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:33.391229 24581 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root
uuid: "766f41ee53c74f3491e95709486d6845"
format_stamp: "Formatted at 2026-08-12 06:18:33 on dist-test-slave-g170"
I20260812 06:18:33.391321 24581 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-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:33.402633 24581 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:33.402988 24581 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:33.403283 24581 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:33.403749 24581 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:33.403810 24581 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:33.403872 24581 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:33.403904 24581 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:33.408401 24581 rpc_server.cc:307] RPC server started. Bound to: 127.24.1.65:43401
I20260812 06:18:33.408427 25196 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.1.65:43401 every 8 connection(s)
I20260812 06:18:33.413493 25198 heartbeater.cc:344] Connected to a master server at 127.24.1.126:36557
I20260812 06:18:33.413594 25198 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:33.413763 25198 heartbeater.cc:507] Master 127.24.1.126:36557 requested a full tablet report, sending...
I20260812 06:18:33.414388 24983 ts_manager.cc:194] Registered new tserver with Master: 766f41ee53c74f3491e95709486d6845 (127.24.1.65:43401)
I20260812 06:18:33.414541 24581 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.005631348s
I20260812 06:18:33.415227 24983 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:57880
I20260812 06:18:33.421733 24983 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:57886:
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:33.430773 25138 tablet_service.cc:1511] Processing CreateTablet for tablet fe4c0e8c37a94de3bdfc9364a09273b1 (DEFAULT_TABLE table=heavy-update-compaction-test [id=b0e7390fde494391ac8835eed4826241]), partition=
I20260812 06:18:33.431066 25138 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet fe4c0e8c37a94de3bdfc9364a09273b1. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:33.433182 25216 tablet_bootstrap.cc:492] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Bootstrap starting.
I20260812 06:18:33.434087 25216 tablet_bootstrap.cc:654] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:33.435154 25216 tablet_bootstrap.cc:492] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: No bootstrap required, opened a new log
I20260812 06:18:33.435266 25216 ts_tablet_manager.cc:1403] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:33.435681 25216 raft_consensus.cc:359] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "766f41ee53c74f3491e95709486d6845" member_type: VOTER last_known_addr { host: "127.24.1.65" port: 43401 } }
I20260812 06:18:33.435789 25216 raft_consensus.cc:385] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:33.435855 25216 raft_consensus.cc:740] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 766f41ee53c74f3491e95709486d6845, State: Initialized, Role: FOLLOWER
I20260812 06:18:33.435982 25216 consensus_queue.cc:260] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845 [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: "766f41ee53c74f3491e95709486d6845" member_type: VOTER last_known_addr { host: "127.24.1.65" port: 43401 } }
I20260812 06:18:33.436069 25216 raft_consensus.cc:399] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:33.436115 25216 raft_consensus.cc:493] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:33.436169 25216 raft_consensus.cc:3060] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:33.437111 25216 raft_consensus.cc:515] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "766f41ee53c74f3491e95709486d6845" member_type: VOTER last_known_addr { host: "127.24.1.65" port: 43401 } }
I20260812 06:18:33.437227 25216 leader_election.cc:304] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845 [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: 766f41ee53c74f3491e95709486d6845; no voters: 
I20260812 06:18:33.437372 25216 leader_election.cc:290] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:33.437541 25219 raft_consensus.cc:2804] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:33.437705 25216 ts_tablet_manager.cc:1434] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:33.437705 25198 heartbeater.cc:499] Master 127.24.1.126:36557 was elected leader, sending a full tablet report...
I20260812 06:18:33.437770 25219 raft_consensus.cc:697] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845 [term 1 LEADER]: Becoming Leader. State: Replica: 766f41ee53c74f3491e95709486d6845, State: Running, Role: LEADER
I20260812 06:18:33.437978 25219 consensus_queue.cc:237] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845 [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: "766f41ee53c74f3491e95709486d6845" member_type: VOTER last_known_addr { host: "127.24.1.65" port: 43401 } }
I20260812 06:18:33.439244 24983 catalog_manager.cc:5719] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845 reported cstate change: term changed from 0 to 1, leader changed from <none> to 766f41ee53c74f3491e95709486d6845 (127.24.1.65). New cstate: current_term: 1 leader_uuid: "766f41ee53c74f3491e95709486d6845" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "766f41ee53c74f3491e95709486d6845" member_type: VOTER last_known_addr { host: "127.24.1.65" port: 43401 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:33.498718 24581 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.052s	user 0.018s	sys 0.004s
I20260812 06:18:33.659487 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushMRSOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=19.054940
I20260812 06:18:33.817571 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushMRSOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.158s	user 0.111s	sys 0.045s Metrics: {"bytes_written":13620266,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":81,"dirs.run_cpu_time_us":227,"dirs.run_wall_time_us":827,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38668,"lbm_writes_lt_1ms":789,"mutex_wait_us":976,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1660}
I20260812 06:18:33.818462 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling LogGCOp(fe4c0e8c37a94de3bdfc9364a09273b1): free 20290830 bytes of WAL
I20260812 06:18:33.818709 25095 log_reader.cc:385] T fe4c0e8c37a94de3bdfc9364a09273b1: removed 2 log segments from log reader
I20260812 06:18:33.818755 25095 log.cc:1079] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/fe4c0e8c37a94de3bdfc9364a09273b1/wal-000000001 (ops 1-6)
I20260812 06:18:33.818786 25095 log.cc:1079] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/fe4c0e8c37a94de3bdfc9364a09273b1/wal-000000002 (ops 7-10)
I20260812 06:18:33.823581 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: LogGCOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.005s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:33.824023 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling UndoDeltaBlockGCOp(fe4c0e8c37a94de3bdfc9364a09273b1): 16411391 bytes on disk
I20260812 06:18:33.825364 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: UndoDeltaBlockGCOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":110,"lbm_reads_lt_1ms":4}
I20260812 06:18:33.826066 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=1.196750
I20260812 06:18:33.840391 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.014s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3036009,"delete_count":0,"lbm_write_time_us":3632,"lbm_writes_lt_1ms":77,"reinsert_count":0,"update_count":370}
I20260812 06:18:33.840924 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=2.188937
I20260812 06:18:33.851672 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3856509,"delete_count":0,"lbm_write_time_us":4077,"lbm_writes_lt_1ms":97,"reinsert_count":0,"update_count":470}
I20260812 06:18:33.852180 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling MajorDeltaCompactionOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=1.000000
I20260812 06:18:34.042255 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: MajorDeltaCompactionOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.190s	user 0.134s	sys 0.055s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774784,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":630,"lbm_read_time_us":13691,"lbm_reads_lt_1ms":569,"lbm_write_time_us":31125,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":28416,"thread_start_us":337,"threads_started":5,"update_count":2500}
I20260812 06:18:34.042994 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=14.095187
I20260812 06:18:34.097206 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.054s	user 0.023s	sys 0.024s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":21785,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:34.097674 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling MajorDeltaCompactionOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=1.000000
I20260812 06:18:34.246306 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: MajorDeltaCompactionOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.148s	user 0.103s	sys 0.044s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672155,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1007,"lbm_read_time_us":10703,"lbm_reads_lt_1ms":463,"lbm_write_time_us":25521,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":94720,"update_count":2000}
I20260812 06:18:34.246984 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=14.095187
I20260812 06:18:34.306214 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.059s	user 0.030s	sys 0.028s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":26433,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:34.306660 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=2.188937
I20260812 06:18:34.336694 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.030s	user 0.009s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4910,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.337915 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=1.196750
I20260812 06:18:34.345479 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.007s	user 0.006s	sys 0.000s Metrics: {"bytes_written":2338582,"delete_count":0,"lbm_write_time_us":2364,"lbm_writes_lt_1ms":60,"reinsert_count":0,"update_count":285}
I20260812 06:18:34.345984 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=1.000000
I20260812 06:18:34.353555 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.007s	user 0.003s	sys 0.004s Metrics: {"bytes_written":1764227,"delete_count":0,"lbm_write_time_us":2567,"lbm_writes_lt_1ms":46,"reinsert_count":0,"update_count":215}
I20260812 06:18:34.354069 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling MajorDeltaCompactionOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=1.000000
I20260812 06:18:34.580204 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: MajorDeltaCompactionOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.226s	user 0.142s	sys 0.084s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877245,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":245,"lbm_read_time_us":17424,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36819,"lbm_writes_lt_1ms":643,"mutex_wait_us":56,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":3000}
I20260812 06:18:34.580899 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=14.095187
I20260812 06:18:34.644106 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.063s	user 0.040s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22950,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:34.644858 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=2.188937
I20260812 06:18:34.656925 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.012s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4658,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.657404 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling MajorDeltaCompactionOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=1.000000
I20260812 06:18:34.844345 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: MajorDeltaCompactionOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.187s	user 0.106s	sys 0.072s 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":1273,"lbm_read_time_us":14244,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28908,"lbm_writes_lt_1ms":543,"mutex_wait_us":295,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19328,"update_count":2500}
I20260812 06:18:34.845042 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=14.095187
I20260812 06:18:34.910087 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.065s	user 0.039s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19647,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:34.910701 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=2.188937
I20260812 06:18:34.922518 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4540,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.923035 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling MajorDeltaCompactionOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=1.000000
I20260812 06:18:35.113725 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: MajorDeltaCompactionOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.190s	user 0.134s	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":1393,"lbm_read_time_us":13270,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32386,"lbm_writes_lt_1ms":543,"mutex_wait_us":492,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:35.114478 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=10.126437
I20260812 06:18:35.148895 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.034s	user 0.031s	sys 0.003s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15174,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:35.149696 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=2.188937
I20260812 06:18:35.165818 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.016s	user 0.001s	sys 0.014s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5962,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.166438 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushMRSOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=1.000000
I20260812 06:18:35.197353 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushMRSOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.031s	user 0.029s	sys 0.001s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":262,"dirs.run_wall_time_us":1307,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1712,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:35.197909 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling LogGCOp(fe4c0e8c37a94de3bdfc9364a09273b1): free 112692331 bytes of WAL
I20260812 06:18:35.198139 25095 log_reader.cc:385] T fe4c0e8c37a94de3bdfc9364a09273b1: removed 11 log segments from log reader
I20260812 06:18:35.198191 25095 log.cc:1079] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/fe4c0e8c37a94de3bdfc9364a09273b1/wal-000000003 (ops 11-15)
I20260812 06:18:35.198220 25095 log.cc:1079] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/fe4c0e8c37a94de3bdfc9364a09273b1/wal-000000004 (ops 16-20)
I20260812 06:18:35.198282 25095 log.cc:1079] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/fe4c0e8c37a94de3bdfc9364a09273b1/wal-000000005 (ops 21-25)
I20260812 06:18:35.198316 25095 log.cc:1079] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/fe4c0e8c37a94de3bdfc9364a09273b1/wal-000000006 (ops 26-30)
I20260812 06:18:35.198376 25095 log.cc:1079] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/fe4c0e8c37a94de3bdfc9364a09273b1/wal-000000007 (ops 31-35)
I20260812 06:18:35.198396 25095 log.cc:1079] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/fe4c0e8c37a94de3bdfc9364a09273b1/wal-000000008 (ops 36-40)
I20260812 06:18:35.198451 25095 log.cc:1079] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/fe4c0e8c37a94de3bdfc9364a09273b1/wal-000000009 (ops 41-45)
I20260812 06:18:35.198496 25095 log.cc:1079] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/fe4c0e8c37a94de3bdfc9364a09273b1/wal-000000010 (ops 46-50)
I20260812 06:18:35.198536 25095 log.cc:1079] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/fe4c0e8c37a94de3bdfc9364a09273b1/wal-000000011 (ops 51-55)
I20260812 06:18:35.198576 25095 log.cc:1079] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/fe4c0e8c37a94de3bdfc9364a09273b1/wal-000000012 (ops 56-60)
I20260812 06:18:35.198616 25095 log.cc:1079] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/fe4c0e8c37a94de3bdfc9364a09273b1/wal-000000013 (ops 61-65)
I20260812 06:18:35.225298 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: LogGCOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.027s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:18:35.225684 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=6.157687
I20260812 06:18:35.249794 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.024s	user 0.022s	sys 0.000s Metrics: {"bytes_written":7999958,"delete_count":0,"lbm_write_time_us":10404,"lbm_writes_lt_1ms":198,"reinsert_count":0,"update_count":975}
I20260812 06:18:35.250238 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling LogGCOp(fe4c0e8c37a94de3bdfc9364a09273b1): free 8767174 bytes of WAL
I20260812 06:18:35.250448 25095 log_reader.cc:385] T fe4c0e8c37a94de3bdfc9364a09273b1: removed 1 log segments from log reader
I20260812 06:18:35.250494 25095 log.cc:1079] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/fe4c0e8c37a94de3bdfc9364a09273b1/wal-000000014 (ops 66-70)
I20260812 06:18:35.252328 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: LogGCOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:35.252619 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling MajorDeltaCompactionOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=1.000000
I20260812 06:18:35.455785 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: MajorDeltaCompactionOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.203s	user 0.109s	sys 0.093s Metrics: {"cfile_cache_miss":628,"cfile_cache_miss_bytes":28672102,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":170,"lbm_read_time_us":15697,"lbm_reads_lt_1ms":664,"lbm_write_time_us":33795,"lbm_writes_lt_1ms":638,"mutex_wait_us":25,"peak_mem_usage":74296913,"reinsert_count":0,"spinlock_wait_cycles":3584,"thread_start_us":80,"threads_started":1,"update_count":2975}
I20260812 06:18:35.459511 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling UndoDeltaBlockGCOp(fe4c0e8c37a94de3bdfc9364a09273b1): 472 bytes on disk
I20260812 06:18:35.460212 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: UndoDeltaBlockGCOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":106,"lbm_reads_lt_1ms":4}
I20260812 06:18:35.460937 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=15.087375
I20260812 06:18:35.516618 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.055s	user 0.024s	sys 0.028s Metrics: {"bytes_written":16615027,"delete_count":0,"lbm_write_time_us":19391,"lbm_writes_lt_1ms":408,"reinsert_count":0,"update_count":2025}
I20260812 06:18:35.517256 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=2.188937
I20260812 06:18:35.528128 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4234,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.528574 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling MajorDeltaCompactionOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=1.000000
I20260812 06:18:35.721422 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: MajorDeltaCompactionOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.193s	user 0.141s	sys 0.043s Metrics: {"cfile_cache_miss":537,"cfile_cache_miss_bytes":24979814,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":704,"lbm_read_time_us":14189,"lbm_reads_lt_1ms":577,"lbm_write_time_us":30641,"lbm_writes_lt_1ms":548,"mutex_wait_us":44,"peak_mem_usage":63321075,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2525}
I20260812 06:18:35.722071 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=14.095187
I20260812 06:18:35.788645 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.066s	user 0.032s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21492,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:35.789211 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=2.188937
I20260812 06:18:35.800614 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.011s	user 0.005s	sys 0.005s 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:35.801304 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling MajorDeltaCompactionOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=1.000000
I20260812 06:18:35.998247 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: MajorDeltaCompactionOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.197s	user 0.126s	sys 0.060s 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":251,"lbm_read_time_us":14334,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30491,"lbm_writes_lt_1ms":543,"mutex_wait_us":65,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2500}
I20260812 06:18:35.998992 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=14.095187
I20260812 06:18:36.052552 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.053s	user 0.022s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20965,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:36.053082 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=2.188937
I20260812 06:18:36.064445 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4219,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.064965 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling MajorDeltaCompactionOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=1.000000
I20260812 06:18:36.252583 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: MajorDeltaCompactionOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.187s	user 0.137s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":303,"lbm_read_time_us":12696,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28485,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2500}
I20260812 06:18:36.253296 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=14.095187
I20260812 06:18:36.305697 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.052s	user 0.032s	sys 0.019s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":23555,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:36.306198 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=2.188937
I20260812 06:18:36.320070 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5318,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.320505 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling MajorDeltaCompactionOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=1.000000
I20260812 06:18:36.482349 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: MajorDeltaCompactionOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.162s	user 0.134s	sys 0.023s 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":294,"lbm_read_time_us":10675,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30638,"lbm_writes_lt_1ms":543,"mutex_wait_us":34,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":2500}
I20260812 06:18:36.483035 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=14.095187
I20260812 06:18:36.538165 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.055s	user 0.043s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22965,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:36.538697 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=2.188937
I20260812 06:18:36.549214 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.010s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3998,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.549980 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling MajorDeltaCompactionOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=1.000000
I20260812 06:18:36.696941 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: MajorDeltaCompactionOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.147s	user 0.110s	sys 0.028s 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":600,"lbm_read_time_us":9526,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28029,"lbm_writes_lt_1ms":543,"mutex_wait_us":275,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":2500}
I20260812 06:18:36.697719 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=11.118625
I20260812 06:18:36.738189 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.040s	user 0.014s	sys 0.024s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":18437,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:18:36.738979 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=2.188937
I20260812 06:18:36.763430 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.024s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4412,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:36.764036 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=2.188937
I20260812 06:18:36.774516 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.010s	user 0.000s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4062,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.775142 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushMRSOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=1.000000
I20260812 06:18:36.810057 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushMRSOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.035s	user 0.028s	sys 0.005s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":254,"dirs.run_wall_time_us":1424,"drs_written":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1916,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:36.810833 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling LogGCOp(fe4c0e8c37a94de3bdfc9364a09273b1): free 124257201 bytes of WAL
I20260812 06:18:36.811108 25095 log_reader.cc:385] T fe4c0e8c37a94de3bdfc9364a09273b1: removed 12 log segments from log reader
I20260812 06:18:36.811182 25095 log.cc:1079] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/fe4c0e8c37a94de3bdfc9364a09273b1/wal-000000015 (ops 71-75)
I20260812 06:18:36.811241 25095 log.cc:1079] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/fe4c0e8c37a94de3bdfc9364a09273b1/wal-000000016 (ops 76-80)
I20260812 06:18:36.811304 25095 log.cc:1079] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/fe4c0e8c37a94de3bdfc9364a09273b1/wal-000000017 (ops 81-85)
I20260812 06:18:36.811354 25095 log.cc:1079] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/fe4c0e8c37a94de3bdfc9364a09273b1/wal-000000018 (ops 86-90)
I20260812 06:18:36.811398 25095 log.cc:1079] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/fe4c0e8c37a94de3bdfc9364a09273b1/wal-000000019 (ops 91-95)
I20260812 06:18:36.811432 25095 log.cc:1079] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/fe4c0e8c37a94de3bdfc9364a09273b1/wal-000000020 (ops 96-100)
I20260812 06:18:36.811470 25095 log.cc:1079] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/fe4c0e8c37a94de3bdfc9364a09273b1/wal-000000021 (ops 101-105)
I20260812 06:18:36.811508 25095 log.cc:1079] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/fe4c0e8c37a94de3bdfc9364a09273b1/wal-000000022 (ops 106-110)
I20260812 06:18:36.811546 25095 log.cc:1079] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/fe4c0e8c37a94de3bdfc9364a09273b1/wal-000000023 (ops 111-114)
I20260812 06:18:36.811583 25095 log.cc:1079] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/fe4c0e8c37a94de3bdfc9364a09273b1/wal-000000024 (ops 115-119)
I20260812 06:18:36.811625 25095 log.cc:1079] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/fe4c0e8c37a94de3bdfc9364a09273b1/wal-000000025 (ops 120-124)
I20260812 06:18:36.811668 25095 log.cc:1079] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/fe4c0e8c37a94de3bdfc9364a09273b1/wal-000000026 (ops 125-129)
I20260812 06:18:36.840955 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: LogGCOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.030s	user 0.003s	sys 0.027s Metrics: {}
I20260812 06:18:36.841531 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling UndoDeltaBlockGCOp(fe4c0e8c37a94de3bdfc9364a09273b1): 483 bytes on disk
I20260812 06:18:36.842161 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: UndoDeltaBlockGCOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":82,"lbm_reads_lt_1ms":4}
I20260812 06:18:36.843010 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=3.181125
I20260812 06:18:36.861766 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.019s	user 0.012s	sys 0.005s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7632,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:36.862236 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=2.188937
I20260812 06:18:36.872867 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.010s	user 0.005s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3989,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:36.873571 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling MajorDeltaCompactionOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=1.000000
I20260812 06:18:37.114054 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: MajorDeltaCompactionOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.240s	user 0.121s	sys 0.105s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979850,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":534,"lbm_read_time_us":15004,"lbm_reads_lt_1ms":775,"lbm_write_time_us":38067,"lbm_writes_lt_1ms":743,"mutex_wait_us":22,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":10496,"thread_start_us":78,"threads_started":1,"update_count":3500}
I20260812 06:18:37.114835 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=18.063937
I20260812 06:18:37.189144 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.074s	user 0.051s	sys 0.023s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":28785,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:37.189764 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=2.188937
I20260812 06:18:37.200796 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4322,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.201252 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling MajorDeltaCompactionOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=1.000000
I20260812 06:18:37.399916 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: MajorDeltaCompactionOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.198s	user 0.132s	sys 0.066s 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":641,"lbm_read_time_us":14234,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33956,"lbm_writes_lt_1ms":643,"mutex_wait_us":320,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:18:37.404122 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=14.095187
I20260812 06:18:37.459076 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.055s	user 0.030s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22858,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:37.459652 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=2.188937
I20260812 06:18:37.474771 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5772,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.475291 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling MajorDeltaCompactionOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=1.000000
I20260812 06:18:37.660266 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: MajorDeltaCompactionOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.185s	user 0.126s	sys 0.047s 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":1955,"lbm_read_time_us":15403,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27907,"lbm_writes_lt_1ms":543,"mutex_wait_us":583,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19456,"update_count":2500}
I20260812 06:18:37.660990 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=14.095187
I20260812 06:18:37.730158 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.069s	user 0.032s	sys 0.036s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":28088,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:37.730701 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=2.188937
I20260812 06:18:37.741273 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4139,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.741698 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling MajorDeltaCompactionOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=1.000000
I20260812 06:18:37.933187 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: MajorDeltaCompactionOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.191s	user 0.123s	sys 0.060s 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":761,"lbm_read_time_us":12851,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31386,"lbm_writes_lt_1ms":543,"mutex_wait_us":71,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2500}
I20260812 06:18:37.933807 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=14.095187
I20260812 06:18:38.000211 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.066s	user 0.039s	sys 0.023s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":22706,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:38.000902 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=2.188937
I20260812 06:18:38.017689 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.017s	user 0.007s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6315,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.018323 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling MajorDeltaCompactionOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=1.000000
I20260812 06:18:38.208055 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: MajorDeltaCompactionOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.189s	user 0.099s	sys 0.077s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":402,"lbm_read_time_us":12913,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29113,"lbm_writes_lt_1ms":543,"mutex_wait_us":73,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2500}
I20260812 06:18:38.208734 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=14.095187
I20260812 06:18:38.258563 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.050s	user 0.031s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21820,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:38.259027 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=2.188937
I20260812 06:18:38.282300 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.023s	user 0.003s	sys 0.019s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4644,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.283039 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushMRSOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=1.000000
I20260812 06:18:38.319069 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushMRSOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.036s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":234,"dirs.run_wall_time_us":1552,"drs_written":1,"lbm_read_time_us":83,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2189,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:38.319875 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling LogGCOp(fe4c0e8c37a94de3bdfc9364a09273b1): free 120553638 bytes of WAL
I20260812 06:18:38.320125 25095 log_reader.cc:385] T fe4c0e8c37a94de3bdfc9364a09273b1: removed 12 log segments from log reader
I20260812 06:18:38.320169 25095 log.cc:1079] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/fe4c0e8c37a94de3bdfc9364a09273b1/wal-000000027 (ops 130-134)
I20260812 06:18:38.320199 25095 log.cc:1079] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/fe4c0e8c37a94de3bdfc9364a09273b1/wal-000000028 (ops 135-139)
I20260812 06:18:38.320242 25095 log.cc:1079] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/fe4c0e8c37a94de3bdfc9364a09273b1/wal-000000029 (ops 140-144)
I20260812 06:18:38.320286 25095 log.cc:1079] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/fe4c0e8c37a94de3bdfc9364a09273b1/wal-000000030 (ops 145-149)
I20260812 06:18:38.320333 25095 log.cc:1079] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/fe4c0e8c37a94de3bdfc9364a09273b1/wal-000000031 (ops 150-154)
I20260812 06:18:38.320374 25095 log.cc:1079] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/fe4c0e8c37a94de3bdfc9364a09273b1/wal-000000032 (ops 155-159)
I20260812 06:18:38.320432 25095 log.cc:1079] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/fe4c0e8c37a94de3bdfc9364a09273b1/wal-000000033 (ops 160-164)
I20260812 06:18:38.320472 25095 log.cc:1079] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/fe4c0e8c37a94de3bdfc9364a09273b1/wal-000000034 (ops 165-168)
I20260812 06:18:38.320515 25095 log.cc:1079] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/fe4c0e8c37a94de3bdfc9364a09273b1/wal-000000035 (ops 169-173)
I20260812 06:18:38.320556 25095 log.cc:1079] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/fe4c0e8c37a94de3bdfc9364a09273b1/wal-000000036 (ops 174-178)
I20260812 06:18:38.320595 25095 log.cc:1079] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/fe4c0e8c37a94de3bdfc9364a09273b1/wal-000000037 (ops 179-182)
I20260812 06:18:38.320634 25095 log.cc:1079] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: Deleting log segment in path: /tmp/dist-test-task7eU7Ij/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515507599707-24581-0/minicluster-data/ts-0-root/wals/fe4c0e8c37a94de3bdfc9364a09273b1/wal-000000038 (ops 183-187)
I20260812 06:18:38.348023 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: LogGCOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:38.348495 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling UndoDeltaBlockGCOp(fe4c0e8c37a94de3bdfc9364a09273b1): 447 bytes on disk
I20260812 06:18:38.349046 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: UndoDeltaBlockGCOp(fe4c0e8c37a94de3bdfc9364a09273b1) 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:38.349614 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=2.188937
I20260812 06:18:38.372488 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.023s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6357,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.372977 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=2.188937
I20260812 06:18:38.383456 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3978,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.384027 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling MajorDeltaCompactionOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=1.000000
I20260812 06:18:38.620688 24581 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.122s	user 1.813s	sys 0.246s
I20260812 06:18:38.637137 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: MajorDeltaCompactionOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.253s	user 0.169s	sys 0.082s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979750,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":584,"lbm_read_time_us":15282,"lbm_reads_lt_1ms":774,"lbm_write_time_us":41992,"lbm_writes_lt_1ms":743,"mutex_wait_us":61,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":9344,"thread_start_us":82,"threads_started":1,"update_count":3500}
I20260812 06:18:38.641351 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=18.063937
I20260812 06:18:38.685825 24581 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.065s	user 0.005s	sys 0.000s
I20260812 06:18:38.686360 24581 tablet_server.cc:179] TabletServer@127.24.1.65:0 shutting down...
I20260812 06:18:38.689795 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: FlushDeltaMemStoresOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.048s	user 0.019s	sys 0.028s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":21876,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:38.690425 25199 maintenance_manager.cc:419] P 766f41ee53c74f3491e95709486d6845: Scheduling MajorDeltaCompactionOp(fe4c0e8c37a94de3bdfc9364a09273b1): perf score=1.000000
I20260812 06:18:38.831607 25095 maintenance_manager.cc:643] P 766f41ee53c74f3491e95709486d6845: MajorDeltaCompactionOp(fe4c0e8c37a94de3bdfc9364a09273b1) complete. Timing: real 0.141s	user 0.107s	sys 0.033s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4262390,"cfile_cache_miss":501,"cfile_cache_miss_bytes":20512182,"cfile_init":3,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1308,"lbm_read_time_us":7769,"lbm_reads_lt_1ms":513,"lbm_write_time_us":24280,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:38.832232 24581 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:38.832510 24581 tablet_replica.cc:333] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845: stopping tablet replica
I20260812 06:18:38.832723 24581 raft_consensus.cc:2243] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:38.832939 24581 raft_consensus.cc:2272] T fe4c0e8c37a94de3bdfc9364a09273b1 P 766f41ee53c74f3491e95709486d6845 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:38.846737 24581 tablet_server.cc:196] TabletServer@127.24.1.65:0 shutdown complete.
I20260812 06:18:38.879258 24581 master.cc:562] Master@127.24.1.126:36557 shutting down...
I20260812 06:18:38.883324 24581 raft_consensus.cc:2243] T 00000000000000000000000000000000 P b6c3947b8d704924a496a7e12e256239 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:38.883538 24581 raft_consensus.cc:2272] T 00000000000000000000000000000000 P b6c3947b8d704924a496a7e12e256239 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:38.883638 24581 tablet_replica.cc:333] T 00000000000000000000000000000000 P b6c3947b8d704924a496a7e12e256239: stopping tablet replica
I20260812 06:18:38.896121 24581 master.cc:584] Master@127.24.1.126:36557 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5720 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11382 ms total)

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