[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:19:32.600543 18300 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.17.223.62:46641
I20260812 06:19:32.601619 18300 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:19:32.602310 18300 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:32.611726 18308 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:32.611858 18300 server_base.cc:1061] running on GCE node
W20260812 06:19:32.611714 18311 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:32.612066 18309 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:32.612684 18300 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:32.612803 18300 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:32.612841 18300 hybrid_clock.cc:648] HybridClock initialized: now 1786515572612839 us; error 0 us; skew 500 ppm
I20260812 06:19:32.614964 18300 webserver.cc:533] Webserver started at http://127.17.223.62:45713/ using document root <none> and password file <none>
I20260812 06:19:32.615690 18300 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:32.615760 18300 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:32.616003 18300 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:32.617728 18300 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/master-0-root/instance:
uuid: "00ff8d29b614438aa2b43e5d812b0a5d"
format_stamp: "Formatted at 2026-08-12 06:19:32 on dist-test-slave-mn4r"
I20260812 06:19:32.621448 18300 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:32.623813 18317 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:32.624975 18300 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.000s	sys 0.001s
I20260812 06:19:32.625154 18300 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/master-0-root
uuid: "00ff8d29b614438aa2b43e5d812b0a5d"
format_stamp: "Formatted at 2026-08-12 06:19:32 on dist-test-slave-mn4r"
I20260812 06:19:32.625269 18300 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:32.656047 18300 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:32.656806 18300 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:19:32.657023 18300 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:32.665879 18300 rpc_server.cc:307] RPC server started. Bound to: 127.17.223.62:46641
I20260812 06:19:32.665894 18381 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.17.223.62:46641 every 8 connection(s)
I20260812 06:19:32.668506 18382 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:32.674431 18382 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 00ff8d29b614438aa2b43e5d812b0a5d: Bootstrap starting.
I20260812 06:19:32.677139 18382 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 00ff8d29b614438aa2b43e5d812b0a5d: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:32.678156 18382 log.cc:826] T 00000000000000000000000000000000 P 00ff8d29b614438aa2b43e5d812b0a5d: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:32.680028 18382 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 00ff8d29b614438aa2b43e5d812b0a5d: No bootstrap required, opened a new log
I20260812 06:19:32.683076 18382 raft_consensus.cc:359] T 00000000000000000000000000000000 P 00ff8d29b614438aa2b43e5d812b0a5d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "00ff8d29b614438aa2b43e5d812b0a5d" member_type: VOTER }
I20260812 06:19:32.683248 18382 raft_consensus.cc:385] T 00000000000000000000000000000000 P 00ff8d29b614438aa2b43e5d812b0a5d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:32.683292 18382 raft_consensus.cc:740] T 00000000000000000000000000000000 P 00ff8d29b614438aa2b43e5d812b0a5d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 00ff8d29b614438aa2b43e5d812b0a5d, State: Initialized, Role: FOLLOWER
I20260812 06:19:32.683859 18382 consensus_queue.cc:260] T 00000000000000000000000000000000 P 00ff8d29b614438aa2b43e5d812b0a5d [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: "00ff8d29b614438aa2b43e5d812b0a5d" member_type: VOTER }
I20260812 06:19:32.683992 18382 raft_consensus.cc:399] T 00000000000000000000000000000000 P 00ff8d29b614438aa2b43e5d812b0a5d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:32.684042 18382 raft_consensus.cc:493] T 00000000000000000000000000000000 P 00ff8d29b614438aa2b43e5d812b0a5d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:32.684131 18382 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 00ff8d29b614438aa2b43e5d812b0a5d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:32.684903 18382 raft_consensus.cc:515] T 00000000000000000000000000000000 P 00ff8d29b614438aa2b43e5d812b0a5d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "00ff8d29b614438aa2b43e5d812b0a5d" member_type: VOTER }
I20260812 06:19:32.685325 18382 leader_election.cc:304] T 00000000000000000000000000000000 P 00ff8d29b614438aa2b43e5d812b0a5d [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: 00ff8d29b614438aa2b43e5d812b0a5d; no voters: 
I20260812 06:19:32.685632 18382 leader_election.cc:290] T 00000000000000000000000000000000 P 00ff8d29b614438aa2b43e5d812b0a5d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:32.685832 18387 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 00ff8d29b614438aa2b43e5d812b0a5d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:32.686205 18387 raft_consensus.cc:697] T 00000000000000000000000000000000 P 00ff8d29b614438aa2b43e5d812b0a5d [term 1 LEADER]: Becoming Leader. State: Replica: 00ff8d29b614438aa2b43e5d812b0a5d, State: Running, Role: LEADER
I20260812 06:19:32.686682 18387 consensus_queue.cc:237] T 00000000000000000000000000000000 P 00ff8d29b614438aa2b43e5d812b0a5d [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: "00ff8d29b614438aa2b43e5d812b0a5d" member_type: VOTER }
I20260812 06:19:32.686772 18382 sys_catalog.cc:565] T 00000000000000000000000000000000 P 00ff8d29b614438aa2b43e5d812b0a5d [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:32.689117 18300 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:32.689109 18388 sys_catalog.cc:455] T 00000000000000000000000000000000 P 00ff8d29b614438aa2b43e5d812b0a5d [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "00ff8d29b614438aa2b43e5d812b0a5d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "00ff8d29b614438aa2b43e5d812b0a5d" member_type: VOTER } }
I20260812 06:19:32.689234 18388 sys_catalog.cc:458] T 00000000000000000000000000000000 P 00ff8d29b614438aa2b43e5d812b0a5d [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:32.689347 18389 sys_catalog.cc:455] T 00000000000000000000000000000000 P 00ff8d29b614438aa2b43e5d812b0a5d [sys.catalog]: SysCatalogTable state changed. Reason: New leader 00ff8d29b614438aa2b43e5d812b0a5d. Latest consensus state: current_term: 1 leader_uuid: "00ff8d29b614438aa2b43e5d812b0a5d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "00ff8d29b614438aa2b43e5d812b0a5d" member_type: VOTER } }
I20260812 06:19:32.689419 18389 sys_catalog.cc:458] T 00000000000000000000000000000000 P 00ff8d29b614438aa2b43e5d812b0a5d [sys.catalog]: This master's current role is: LEADER
W20260812 06:19:32.691560 18401 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 00ff8d29b614438aa2b43e5d812b0a5d: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:19:32.691636 18401 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:19:32.691779 18402 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:32.692644 18402 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:32.698071 18402 catalog_manager.cc:1383] Generated new cluster ID: 14a1c5ac0da24fafbfcd0a11243aa59f
I20260812 06:19:32.698174 18402 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:32.713467 18402 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:32.714525 18402 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:32.725059 18402 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 00ff8d29b614438aa2b43e5d812b0a5d: Generated new TSK 0
I20260812 06:19:32.725744 18402 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:32.754492 18300 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:32.757517 18406 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:32.757516 18409 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:32.757534 18407 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:32.758137 18300 server_base.cc:1061] running on GCE node
I20260812 06:19:32.758330 18300 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:32.758394 18300 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:32.758445 18300 hybrid_clock.cc:648] HybridClock initialized: now 1786515572758444 us; error 0 us; skew 500 ppm
I20260812 06:19:32.759411 18300 webserver.cc:533] Webserver started at http://127.17.223.1:33993/ using document root <none> and password file <none>
I20260812 06:19:32.759624 18300 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:32.759701 18300 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:32.759785 18300 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:32.760205 18300 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root/instance:
uuid: "8e5f1b2213ef47619bd89534eb4f551a"
format_stamp: "Formatted at 2026-08-12 06:19:32 on dist-test-slave-mn4r"
I20260812 06:19:32.761869 18300 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:32.763156 18416 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:32.763480 18300 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:32.763547 18300 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root
uuid: "8e5f1b2213ef47619bd89534eb4f551a"
format_stamp: "Formatted at 2026-08-12 06:19:32 on dist-test-slave-mn4r"
I20260812 06:19:32.763643 18300 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:32.784705 18300 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:32.785245 18300 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:32.785935 18300 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:32.786871 18300 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:32.786926 18300 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:32.786984 18300 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:32.787045 18300 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:32.794512 18300 rpc_server.cc:307] RPC server started. Bound to: 127.17.223.1:40205
I20260812 06:19:32.794565 18493 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.17.223.1:40205 every 8 connection(s)
I20260812 06:19:32.810964 18495 heartbeater.cc:344] Connected to a master server at 127.17.223.62:46641
I20260812 06:19:32.811290 18495 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:32.811856 18495 heartbeater.cc:507] Master 127.17.223.62:46641 requested a full tablet report, sending...
I20260812 06:19:32.813755 18340 ts_manager.cc:194] Registered new tserver with Master: 8e5f1b2213ef47619bd89534eb4f551a (127.17.223.1:40205)
I20260812 06:19:32.813825 18300 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.018492314s
I20260812 06:19:32.815368 18340 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:33968
I20260812 06:19:32.825237 18340 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:33980:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:32.840837 18451 tablet_service.cc:1511] Processing CreateTablet for tablet 454e533abdbc4aa7b285e23eea1a8583 (DEFAULT_TABLE table=heavy-update-compaction-test [id=0f39b7b4a7274660ac9cc2003550bf76]), partition=
I20260812 06:19:32.841401 18451 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 454e533abdbc4aa7b285e23eea1a8583. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:32.844249 18510 tablet_bootstrap.cc:492] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Bootstrap starting.
I20260812 06:19:32.845690 18510 tablet_bootstrap.cc:654] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:32.847043 18510 tablet_bootstrap.cc:492] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: No bootstrap required, opened a new log
I20260812 06:19:32.847178 18510 ts_tablet_manager.cc:1403] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Time spent bootstrapping tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:19:32.847678 18510 raft_consensus.cc:359] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8e5f1b2213ef47619bd89534eb4f551a" member_type: VOTER last_known_addr { host: "127.17.223.1" port: 40205 } }
I20260812 06:19:32.847818 18510 raft_consensus.cc:385] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:32.847895 18510 raft_consensus.cc:740] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8e5f1b2213ef47619bd89534eb4f551a, State: Initialized, Role: FOLLOWER
I20260812 06:19:32.848088 18510 consensus_queue.cc:260] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a [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: "8e5f1b2213ef47619bd89534eb4f551a" member_type: VOTER last_known_addr { host: "127.17.223.1" port: 40205 } }
I20260812 06:19:32.848268 18510 raft_consensus.cc:399] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:32.848369 18510 raft_consensus.cc:493] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:32.848434 18510 raft_consensus.cc:3060] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:32.849382 18510 raft_consensus.cc:515] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8e5f1b2213ef47619bd89534eb4f551a" member_type: VOTER last_known_addr { host: "127.17.223.1" port: 40205 } }
I20260812 06:19:32.849545 18510 leader_election.cc:304] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a [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: 8e5f1b2213ef47619bd89534eb4f551a; no voters: 
I20260812 06:19:32.849794 18510 leader_election.cc:290] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:32.849900 18512 raft_consensus.cc:2804] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:32.850098 18512 raft_consensus.cc:697] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a [term 1 LEADER]: Becoming Leader. State: Replica: 8e5f1b2213ef47619bd89534eb4f551a, State: Running, Role: LEADER
I20260812 06:19:32.850247 18510 ts_tablet_manager.cc:1434] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:19:32.850315 18512 consensus_queue.cc:237] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a [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: "8e5f1b2213ef47619bd89534eb4f551a" member_type: VOTER last_known_addr { host: "127.17.223.1" port: 40205 } }
I20260812 06:19:32.850551 18495 heartbeater.cc:499] Master 127.17.223.62:46641 was elected leader, sending a full tablet report...
I20260812 06:19:32.853689 18340 catalog_manager.cc:5719] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a reported cstate change: term changed from 0 to 1, leader changed from <none> to 8e5f1b2213ef47619bd89534eb4f551a (127.17.223.1). New cstate: current_term: 1 leader_uuid: "8e5f1b2213ef47619bd89534eb4f551a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8e5f1b2213ef47619bd89534eb4f551a" member_type: VOTER last_known_addr { host: "127.17.223.1" port: 40205 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:32.921372 18300 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.059s	user 0.014s	sys 0.012s
I20260812 06:19:33.045786 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushMRSOp(454e533abdbc4aa7b285e23eea1a8583): perf score=15.086190
I20260812 06:19:33.213768 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushMRSOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.167s	user 0.133s	sys 0.023s Metrics: {"bytes_written":11897250,"cfile_init":1,"compiler_manager_pool.queue_time_us":228,"delete_count":0,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":301,"dirs.run_wall_time_us":1088,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42242,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":136,"threads_started":1,"update_count":1450}
I20260812 06:19:33.215193 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling LogGCOp(454e533abdbc4aa7b285e23eea1a8583): free 20743880 bytes of WAL
I20260812 06:19:33.215533 18423 log_reader.cc:385] T 454e533abdbc4aa7b285e23eea1a8583: removed 2 log segments from log reader
I20260812 06:19:33.215603 18423 log.cc:1079] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/454e533abdbc4aa7b285e23eea1a8583/wal-000000001 (ops 1-6)
I20260812 06:19:33.215658 18423 log.cc:1079] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/454e533abdbc4aa7b285e23eea1a8583/wal-000000002 (ops 7-11)
I20260812 06:19:33.221195 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: LogGCOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.006s	user 0.003s	sys 0.000s Metrics: {}
I20260812 06:19:33.221575 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=2.188937
I20260812 06:19:33.243316 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.022s	user 0.014s	sys 0.003s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":7259,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:33.243809 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling MajorDeltaCompactionOp(454e533abdbc4aa7b285e23eea1a8583): perf score=1.000000
I20260812 06:19:33.384523 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: MajorDeltaCompactionOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.141s	user 0.101s	sys 0.039s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262038,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":426,"lbm_read_time_us":8729,"lbm_reads_lt_1ms":454,"lbm_write_time_us":29276,"lbm_writes_lt_1ms":433,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":304,"threads_started":5,"update_count":1950}
I20260812 06:19:33.385066 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling UndoDeltaBlockGCOp(454e533abdbc4aa7b285e23eea1a8583): 12719216 bytes on disk
I20260812 06:19:33.385564 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: UndoDeltaBlockGCOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:19:33.386152 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=10.126437
I20260812 06:19:33.431648 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.045s	user 0.012s	sys 0.028s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18275,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:33.432307 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=2.188937
I20260812 06:19:33.443859 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4013,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:33.444319 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling MajorDeltaCompactionOp(454e533abdbc4aa7b285e23eea1a8583): perf score=1.000000
I20260812 06:19:33.570148 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: MajorDeltaCompactionOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.126s	user 0.101s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":873,"lbm_read_time_us":9117,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24521,"lbm_writes_lt_1ms":443,"mutex_wait_us":303,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2000}
I20260812 06:19:33.570794 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=10.126437
I20260812 06:19:33.612363 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.041s	user 0.019s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18472,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:33.612859 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=2.188937
I20260812 06:19:33.624254 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4029,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:33.624727 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling MajorDeltaCompactionOp(454e533abdbc4aa7b285e23eea1a8583): perf score=1.000000
I20260812 06:19:33.755115 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: MajorDeltaCompactionOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.130s	user 0.114s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":145,"lbm_read_time_us":9757,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25569,"lbm_writes_lt_1ms":443,"mutex_wait_us":36,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":63872,"update_count":2000}
I20260812 06:19:33.755738 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=10.126437
I20260812 06:19:33.802067 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.046s	user 0.027s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17033,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:19:33.802646 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=2.188937
I20260812 06:19:33.823045 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.020s	user 0.007s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6894,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:33.823589 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling MajorDeltaCompactionOp(454e533abdbc4aa7b285e23eea1a8583): perf score=1.000000
I20260812 06:19:33.981781 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: MajorDeltaCompactionOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.158s	user 0.109s	sys 0.038s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":780,"lbm_read_time_us":9024,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25598,"lbm_writes_lt_1ms":443,"mutex_wait_us":330,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:33.982362 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=14.095187
I20260812 06:19:34.033185 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.051s	user 0.034s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22603,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:34.033731 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=2.188937
I20260812 06:19:34.045809 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4002,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:34.046469 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling MajorDeltaCompactionOp(454e533abdbc4aa7b285e23eea1a8583): perf score=1.000000
I20260812 06:19:34.208003 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: MajorDeltaCompactionOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.161s	user 0.125s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":294,"lbm_read_time_us":11720,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33454,"lbm_writes_lt_1ms":543,"mutex_wait_us":76,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":2500}
I20260812 06:19:34.208619 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=10.126437
I20260812 06:19:34.243119 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.034s	user 0.022s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15532,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:34.243841 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=2.188937
I20260812 06:19:34.262068 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.018s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7090,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:34.262739 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling MajorDeltaCompactionOp(454e533abdbc4aa7b285e23eea1a8583): perf score=1.000000
I20260812 06:19:34.387503 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: MajorDeltaCompactionOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.125s	user 0.078s	sys 0.046s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":320,"lbm_read_time_us":7812,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24784,"lbm_writes_lt_1ms":443,"mutex_wait_us":64,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:19:34.390110 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=10.126437
I20260812 06:19:34.435364 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.045s	user 0.014s	sys 0.021s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16155,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:34.435946 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=2.188937
I20260812 06:19:34.447510 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4058,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:34.448072 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushMRSOp(454e533abdbc4aa7b285e23eea1a8583): perf score=1.000000
I20260812 06:19:34.480882 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushMRSOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.033s	user 0.030s	sys 0.001s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":213,"dirs.run_wall_time_us":1472,"drs_written":1,"lbm_read_time_us":122,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1543,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:34.481748 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling LogGCOp(454e533abdbc4aa7b285e23eea1a8583): free 108535453 bytes of WAL
I20260812 06:19:34.482041 18423 log_reader.cc:385] T 454e533abdbc4aa7b285e23eea1a8583: removed 11 log segments from log reader
I20260812 06:19:34.482134 18423 log.cc:1079] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/454e533abdbc4aa7b285e23eea1a8583/wal-000000003 (ops 12-16)
I20260812 06:19:34.482203 18423 log.cc:1079] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/454e533abdbc4aa7b285e23eea1a8583/wal-000000004 (ops 17-20)
I20260812 06:19:34.482251 18423 log.cc:1079] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/454e533abdbc4aa7b285e23eea1a8583/wal-000000005 (ops 21-25)
I20260812 06:19:34.482311 18423 log.cc:1079] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/454e533abdbc4aa7b285e23eea1a8583/wal-000000006 (ops 26-30)
I20260812 06:19:34.482354 18423 log.cc:1079] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/454e533abdbc4aa7b285e23eea1a8583/wal-000000007 (ops 31-34)
I20260812 06:19:34.482396 18423 log.cc:1079] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/454e533abdbc4aa7b285e23eea1a8583/wal-000000008 (ops 35-39)
I20260812 06:19:34.482438 18423 log.cc:1079] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/454e533abdbc4aa7b285e23eea1a8583/wal-000000009 (ops 40-44)
I20260812 06:19:34.482479 18423 log.cc:1079] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/454e533abdbc4aa7b285e23eea1a8583/wal-000000010 (ops 45-49)
I20260812 06:19:34.482522 18423 log.cc:1079] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/454e533abdbc4aa7b285e23eea1a8583/wal-000000011 (ops 50-54)
I20260812 06:19:34.482563 18423 log.cc:1079] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/454e533abdbc4aa7b285e23eea1a8583/wal-000000012 (ops 55-59)
I20260812 06:19:34.482604 18423 log.cc:1079] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/454e533abdbc4aa7b285e23eea1a8583/wal-000000013 (ops 60-64)
I20260812 06:19:34.511559 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: LogGCOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.030s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:19:34.512036 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling UndoDeltaBlockGCOp(454e533abdbc4aa7b285e23eea1a8583): 448 bytes on disk
I20260812 06:19:34.512530 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: UndoDeltaBlockGCOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:19:34.513152 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=3.181125
I20260812 06:19:34.526990 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.014s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":5418,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:34.527478 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling LogGCOp(454e533abdbc4aa7b285e23eea1a8583): free 11564875 bytes of WAL
I20260812 06:19:34.527709 18423 log_reader.cc:385] T 454e533abdbc4aa7b285e23eea1a8583: removed 1 log segments from log reader
I20260812 06:19:34.527760 18423 log.cc:1079] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/454e533abdbc4aa7b285e23eea1a8583/wal-000000014 (ops 65-68)
I20260812 06:19:34.530503 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: LogGCOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:34.530840 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=2.188937
I20260812 06:19:34.544112 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.013s	user 0.010s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4388,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:34.544639 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling MajorDeltaCompactionOp(454e533abdbc4aa7b285e23eea1a8583): perf score=1.000000
I20260812 06:19:34.729615 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: MajorDeltaCompactionOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.185s	user 0.122s	sys 0.056s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877326,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":497,"lbm_read_time_us":13153,"lbm_reads_lt_1ms":666,"lbm_write_time_us":38318,"lbm_writes_lt_1ms":643,"mutex_wait_us":24,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":22784,"thread_start_us":129,"threads_started":1,"update_count":3000}
I20260812 06:19:34.730310 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=14.095187
I20260812 06:19:34.780505 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.050s	user 0.031s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19473,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:34.781091 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=2.188937
I20260812 06:19:34.798583 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.017s	user 0.013s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6454,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:34.799301 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling MajorDeltaCompactionOp(454e533abdbc4aa7b285e23eea1a8583): perf score=1.000000
I20260812 06:19:34.964452 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: MajorDeltaCompactionOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.165s	user 0.108s	sys 0.056s 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":534,"lbm_read_time_us":11301,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33839,"lbm_writes_lt_1ms":543,"mutex_wait_us":94,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":2500}
I20260812 06:19:34.965468 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=12.110812
I20260812 06:19:35.021250 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.056s	user 0.028s	sys 0.020s Metrics: {"bytes_written":13702313,"delete_count":0,"lbm_write_time_us":22256,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":336,"reinsert_count":0,"update_count":1670}
I20260812 06:19:35.021816 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=1.196750
I20260812 06:19:35.033012 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.011s	user 0.003s	sys 0.004s Metrics: {"bytes_written":3118059,"delete_count":0,"lbm_write_time_us":3004,"lbm_writes_lt_1ms":79,"reinsert_count":0,"update_count":380}
I20260812 06:19:35.033689 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=2.188937
I20260812 06:19:35.043715 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3559,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:35.044260 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling MajorDeltaCompactionOp(454e533abdbc4aa7b285e23eea1a8583): perf score=1.000000
I20260812 06:19:35.221942 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: MajorDeltaCompactionOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.177s	user 0.114s	sys 0.058s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774777,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":560,"lbm_read_time_us":12364,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32192,"lbm_writes_lt_1ms":543,"mutex_wait_us":190,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2500}
I20260812 06:19:35.222823 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=11.118625
I20260812 06:19:35.265699 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.043s	user 0.020s	sys 0.019s Metrics: {"bytes_written":12717740,"delete_count":0,"lbm_write_time_us":15270,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:35.266450 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=2.188937
I20260812 06:19:35.279214 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.012s	user 0.011s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4479,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:35.279881 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling MajorDeltaCompactionOp(454e533abdbc4aa7b285e23eea1a8583): perf score=1.000000
I20260812 06:19:35.451220 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: MajorDeltaCompactionOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.171s	user 0.098s	sys 0.071s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":545,"lbm_read_time_us":10515,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28709,"lbm_writes_lt_1ms":443,"mutex_wait_us":290,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":2000}
I20260812 06:19:35.452126 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=11.118625
I20260812 06:19:35.497406 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.045s	user 0.036s	sys 0.004s Metrics: {"bytes_written":12717738,"delete_count":0,"lbm_write_time_us":18837,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:35.497973 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=2.188937
I20260812 06:19:35.509792 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.012s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4482,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:35.510363 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=2.188937
I20260812 06:19:35.521240 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3962,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:35.522179 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling MajorDeltaCompactionOp(454e533abdbc4aa7b285e23eea1a8583): perf score=1.000000
I20260812 06:19:35.705667 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: MajorDeltaCompactionOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.183s	user 0.134s	sys 0.041s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774802,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1073,"lbm_read_time_us":9759,"lbm_reads_lt_1ms":573,"lbm_write_time_us":37419,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":428,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13568,"update_count":2500}
I20260812 06:19:35.706485 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=11.118625
I20260812 06:19:35.746892 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.040s	user 0.017s	sys 0.022s Metrics: {"bytes_written":13374124,"delete_count":0,"lbm_write_time_us":17942,"lbm_writes_lt_1ms":329,"reinsert_count":0,"update_count":1630}
I20260812 06:19:35.747619 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=1.196750
I20260812 06:19:35.769281 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.021s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3077034,"delete_count":0,"lbm_write_time_us":3757,"lbm_writes_lt_1ms":78,"reinsert_count":0,"update_count":375}
I20260812 06:19:35.769905 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=2.188937
I20260812 06:19:35.781828 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4061634,"delete_count":0,"lbm_write_time_us":4275,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":495}
I20260812 06:19:35.782619 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling MajorDeltaCompactionOp(454e533abdbc4aa7b285e23eea1a8583): perf score=1.000000
I20260812 06:19:35.968892 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: MajorDeltaCompactionOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.186s	user 0.132s	sys 0.048s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774792,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1051,"lbm_read_time_us":11947,"lbm_reads_lt_1ms":573,"lbm_write_time_us":39233,"lbm_writes_lt_1ms":543,"mutex_wait_us":327,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:19:35.969548 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=14.095187
I20260812 06:19:36.024740 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.055s	user 0.031s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25018,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:36.025213 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushMRSOp(454e533abdbc4aa7b285e23eea1a8583): perf score=1.000000
I20260812 06:19:36.065361 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushMRSOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.040s	user 0.024s	sys 0.004s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":50,"dirs.run_cpu_time_us":194,"dirs.run_wall_time_us":1483,"drs_written":1,"lbm_read_time_us":102,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1758,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:36.066557 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=3.181125
I20260812 06:19:36.079516 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.013s	user 0.010s	sys 0.002s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4836,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:36.080080 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling LogGCOp(454e533abdbc4aa7b285e23eea1a8583): free 117302590 bytes of WAL
I20260812 06:19:36.080356 18423 log_reader.cc:385] T 454e533abdbc4aa7b285e23eea1a8583: removed 12 log segments from log reader
I20260812 06:19:36.080418 18423 log.cc:1079] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/454e533abdbc4aa7b285e23eea1a8583/wal-000000015 (ops 69-73)
I20260812 06:19:36.080457 18423 log.cc:1079] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/454e533abdbc4aa7b285e23eea1a8583/wal-000000016 (ops 74-78)
I20260812 06:19:36.080492 18423 log.cc:1079] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/454e533abdbc4aa7b285e23eea1a8583/wal-000000017 (ops 79-82)
I20260812 06:19:36.080528 18423 log.cc:1079] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/454e533abdbc4aa7b285e23eea1a8583/wal-000000018 (ops 83-87)
I20260812 06:19:36.080554 18423 log.cc:1079] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/454e533abdbc4aa7b285e23eea1a8583/wal-000000019 (ops 88-92)
I20260812 06:19:36.080583 18423 log.cc:1079] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/454e533abdbc4aa7b285e23eea1a8583/wal-000000020 (ops 93-96)
I20260812 06:19:36.080605 18423 log.cc:1079] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/454e533abdbc4aa7b285e23eea1a8583/wal-000000021 (ops 97-101)
I20260812 06:19:36.080634 18423 log.cc:1079] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/454e533abdbc4aa7b285e23eea1a8583/wal-000000022 (ops 102-106)
I20260812 06:19:36.080667 18423 log.cc:1079] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/454e533abdbc4aa7b285e23eea1a8583/wal-000000023 (ops 107-111)
I20260812 06:19:36.080701 18423 log.cc:1079] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/454e533abdbc4aa7b285e23eea1a8583/wal-000000024 (ops 112-116)
I20260812 06:19:36.080731 18423 log.cc:1079] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/454e533abdbc4aa7b285e23eea1a8583/wal-000000025 (ops 117-121)
I20260812 06:19:36.080760 18423 log.cc:1079] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/454e533abdbc4aa7b285e23eea1a8583/wal-000000026 (ops 122-126)
I20260812 06:19:36.112708 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: LogGCOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.032s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:19:36.113281 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=2.188937
I20260812 06:19:36.136603 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.023s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4804,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:36.137117 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling LogGCOp(454e533abdbc4aa7b285e23eea1a8583): free 11564883 bytes of WAL
I20260812 06:19:36.137342 18423 log_reader.cc:385] T 454e533abdbc4aa7b285e23eea1a8583: removed 1 log segments from log reader
I20260812 06:19:36.137404 18423 log.cc:1079] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/454e533abdbc4aa7b285e23eea1a8583/wal-000000027 (ops 127-130)
I20260812 06:19:36.139763 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: LogGCOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.002s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:36.140115 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling UndoDeltaBlockGCOp(454e533abdbc4aa7b285e23eea1a8583): 482 bytes on disk
I20260812 06:19:36.140555 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: UndoDeltaBlockGCOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:19:36.141047 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=2.188937
I20260812 06:19:36.162405 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.021s	user 0.013s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4040,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:36.163000 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling MajorDeltaCompactionOp(454e533abdbc4aa7b285e23eea1a8583): perf score=1.000000
I20260812 06:19:36.387775 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: MajorDeltaCompactionOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.225s	user 0.147s	sys 0.068s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979737,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":662,"lbm_read_time_us":15089,"lbm_reads_lt_1ms":774,"lbm_write_time_us":37298,"lbm_writes_lt_1ms":743,"mutex_wait_us":373,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":15360,"thread_start_us":78,"threads_started":1,"update_count":3500}
I20260812 06:19:36.388576 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=18.063937
I20260812 06:19:36.461434 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.073s	user 0.038s	sys 0.016s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":26663,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:36.462066 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=2.188937
I20260812 06:19:36.472747 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4004,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:36.473277 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling MajorDeltaCompactionOp(454e533abdbc4aa7b285e23eea1a8583): perf score=1.000000
I20260812 06:19:36.678309 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: MajorDeltaCompactionOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.205s	user 0.135s	sys 0.068s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877104,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":804,"lbm_read_time_us":15962,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33046,"lbm_writes_lt_1ms":643,"mutex_wait_us":62,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:19:36.679189 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=14.095187
I20260812 06:19:36.730348 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.051s	user 0.042s	sys 0.007s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21218,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:36.731091 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=2.188937
I20260812 06:19:36.743302 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4255,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:36.743847 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling MajorDeltaCompactionOp(454e533abdbc4aa7b285e23eea1a8583): perf score=1.000000
I20260812 06:19:36.923786 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: MajorDeltaCompactionOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.180s	user 0.127s	sys 0.052s 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":779,"lbm_read_time_us":11582,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32632,"lbm_writes_lt_1ms":543,"mutex_wait_us":342,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17664,"update_count":2500}
I20260812 06:19:36.924371 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=14.095187
I20260812 06:19:36.992838 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.068s	user 0.040s	sys 0.026s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25312,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:36.993544 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=2.188937
I20260812 06:19:37.005573 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4247,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:37.006139 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling MajorDeltaCompactionOp(454e533abdbc4aa7b285e23eea1a8583): perf score=1.000000
I20260812 06:19:37.180730 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: MajorDeltaCompactionOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.174s	user 0.108s	sys 0.057s 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":1173,"lbm_read_time_us":11894,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28690,"lbm_writes_lt_1ms":543,"mutex_wait_us":364,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12800,"update_count":2500}
I20260812 06:19:37.181520 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=14.095187
I20260812 06:19:37.248196 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.066s	user 0.031s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23250,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:37.248847 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=2.188937
I20260812 06:19:37.260030 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4276,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:37.260588 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling MajorDeltaCompactionOp(454e533abdbc4aa7b285e23eea1a8583): perf score=1.000000
I20260812 06:19:37.459628 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: MajorDeltaCompactionOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.199s	user 0.145s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":945,"lbm_read_time_us":12476,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35733,"lbm_writes_lt_1ms":543,"mutex_wait_us":370,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8704,"update_count":2500}
I20260812 06:19:37.460496 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=14.095187
I20260812 06:19:37.513782 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.053s	user 0.045s	sys 0.004s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23497,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:37.514410 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=2.188937
I20260812 06:19:37.540853 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.026s	user 0.009s	sys 0.014s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6087,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:37.541503 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushMRSOp(454e533abdbc4aa7b285e23eea1a8583): perf score=1.000000
I20260812 06:19:37.574883 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushMRSOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.033s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":87,"dirs.run_cpu_time_us":206,"dirs.run_wall_time_us":1277,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1530,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:37.575690 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling LogGCOp(454e533abdbc4aa7b285e23eea1a8583): free 108988745 bytes of WAL
I20260812 06:19:37.575986 18423 log_reader.cc:385] T 454e533abdbc4aa7b285e23eea1a8583: removed 11 log segments from log reader
I20260812 06:19:37.576059 18423 log.cc:1079] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/454e533abdbc4aa7b285e23eea1a8583/wal-000000028 (ops 131-135)
I20260812 06:19:37.576099 18423 log.cc:1079] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/454e533abdbc4aa7b285e23eea1a8583/wal-000000029 (ops 136-140)
I20260812 06:19:37.576130 18423 log.cc:1079] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/454e533abdbc4aa7b285e23eea1a8583/wal-000000030 (ops 141-145)
I20260812 06:19:37.576152 18423 log.cc:1079] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/454e533abdbc4aa7b285e23eea1a8583/wal-000000031 (ops 146-150)
I20260812 06:19:37.576181 18423 log.cc:1079] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/454e533abdbc4aa7b285e23eea1a8583/wal-000000032 (ops 151-155)
I20260812 06:19:37.576211 18423 log.cc:1079] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/454e533abdbc4aa7b285e23eea1a8583/wal-000000033 (ops 156-160)
I20260812 06:19:37.576242 18423 log.cc:1079] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/454e533abdbc4aa7b285e23eea1a8583/wal-000000034 (ops 161-164)
I20260812 06:19:37.576270 18423 log.cc:1079] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/454e533abdbc4aa7b285e23eea1a8583/wal-000000035 (ops 165-169)
I20260812 06:19:37.576298 18423 log.cc:1079] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/454e533abdbc4aa7b285e23eea1a8583/wal-000000036 (ops 170-174)
I20260812 06:19:37.576319 18423 log.cc:1079] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/454e533abdbc4aa7b285e23eea1a8583/wal-000000037 (ops 175-179)
I20260812 06:19:37.576351 18423 log.cc:1079] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/454e533abdbc4aa7b285e23eea1a8583/wal-000000038 (ops 180-184)
I20260812 06:19:37.606787 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: LogGCOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:19:37.607280 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=2.188937
I20260812 06:19:37.635514 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.028s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5483,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:37.636103 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling UndoDeltaBlockGCOp(454e533abdbc4aa7b285e23eea1a8583): 448 bytes on disk
I20260812 06:19:37.636552 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: UndoDeltaBlockGCOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:19:37.637095 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=2.188937
I20260812 06:19:37.647825 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.011s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3831,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:37.648491 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling MajorDeltaCompactionOp(454e533abdbc4aa7b285e23eea1a8583): perf score=1.000000
I20260812 06:19:37.885742 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: MajorDeltaCompactionOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.237s	user 0.161s	sys 0.072s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979751,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":473,"lbm_read_time_us":14870,"lbm_reads_lt_1ms":774,"lbm_write_time_us":41639,"lbm_writes_lt_1ms":743,"mutex_wait_us":63,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":108,"threads_started":1,"update_count":3500}
I20260812 06:19:37.886467 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=16.079562
I20260812 06:19:37.960711 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.074s	user 0.036s	sys 0.020s Metrics: {"bytes_written":17599603,"delete_count":0,"lbm_write_time_us":27190,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":430,"reinsert_count":0,"update_count":2145}
I20260812 06:19:37.961234 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583): perf score=5.165500
I20260812 06:19:37.978950 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: FlushDeltaMemStoresOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.018s	user 0.013s	sys 0.003s Metrics: {"bytes_written":7015382,"delete_count":0,"lbm_write_time_us":6759,"lbm_writes_lt_1ms":174,"reinsert_count":0,"update_count":855}
I20260812 06:19:37.979524 18496 maintenance_manager.cc:419] P 8e5f1b2213ef47619bd89534eb4f551a: Scheduling MajorDeltaCompactionOp(454e533abdbc4aa7b285e23eea1a8583): perf score=1.000000
I20260812 06:19:38.003826 18300 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.082s	user 1.939s	sys 0.121s
I20260812 06:19:38.075810 18300 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.071s	user 0.002s	sys 0.000s
I20260812 06:19:38.076526 18300 tablet_server.cc:179] TabletServer@127.17.223.1:0 shutting down...
I20260812 06:19:38.149591 18423 maintenance_manager.cc:643] P 8e5f1b2213ef47619bd89534eb4f551a: MajorDeltaCompactionOp(454e533abdbc4aa7b285e23eea1a8583) complete. Timing: real 0.170s	user 0.097s	sys 0.072s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877107,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":446,"lbm_read_time_us":13495,"lbm_reads_lt_1ms":668,"lbm_write_time_us":32346,"lbm_writes_lt_1ms":643,"mutex_wait_us":88,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":3000}
I20260812 06:19:38.150484 18300 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:38.151042 18300 tablet_replica.cc:333] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a: stopping tablet replica
I20260812 06:19:38.151324 18300 raft_consensus.cc:2243] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:38.151582 18300 raft_consensus.cc:2272] T 454e533abdbc4aa7b285e23eea1a8583 P 8e5f1b2213ef47619bd89534eb4f551a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:38.168432 18300 tablet_server.cc:196] TabletServer@127.17.223.1:0 shutdown complete.
I20260812 06:19:38.204663 18300 master.cc:562] Master@127.17.223.62:46641 shutting down...
I20260812 06:19:38.208504 18300 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 00ff8d29b614438aa2b43e5d812b0a5d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:38.208716 18300 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 00ff8d29b614438aa2b43e5d812b0a5d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:38.208808 18300 tablet_replica.cc:333] T 00000000000000000000000000000000 P 00ff8d29b614438aa2b43e5d812b0a5d: stopping tablet replica
I20260812 06:19:38.221318 18300 master.cc:584] Master@127.17.223.62:46641 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5718 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:38.328926 18300 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.17.223.62:33109
I20260812 06:19:38.329391 18300 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:38.331715 18535 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:38.331748 18536 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:19:38.331902 18538 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:38.332064 18300 server_base.cc:1061] running on GCE node
I20260812 06:19:38.332291 18300 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:38.332333 18300 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:38.332348 18300 hybrid_clock.cc:648] HybridClock initialized: now 1786515578332349 us; error 0 us; skew 500 ppm
I20260812 06:19:38.333349 18300 webserver.cc:533] Webserver started at http://127.17.223.62:45637/ using document root <none> and password file <none>
I20260812 06:19:38.333580 18300 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:38.333635 18300 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:38.333746 18300 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:38.334535 18300 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/master-0-root/instance:
uuid: "e6f0d14ce4724d63a0d9e4b7805d2a5e"
format_stamp: "Formatted at 2026-08-12 06:19:38 on dist-test-slave-mn4r"
I20260812 06:19:38.336113 18300 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:38.337047 18543 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:38.337304 18300 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:38.337378 18300 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/master-0-root
uuid: "e6f0d14ce4724d63a0d9e4b7805d2a5e"
format_stamp: "Formatted at 2026-08-12 06:19:38 on dist-test-slave-mn4r"
I20260812 06:19:38.337435 18300 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:38.345980 18300 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:38.346421 18300 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:38.350723 18300 rpc_server.cc:307] RPC server started. Bound to: 127.17.223.62:33109
I20260812 06:19:38.353087 18603 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.17.223.62:33109 every 8 connection(s)
I20260812 06:19:38.353734 18604 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:38.360565 18604 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e6f0d14ce4724d63a0d9e4b7805d2a5e: Bootstrap starting.
I20260812 06:19:38.361579 18604 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P e6f0d14ce4724d63a0d9e4b7805d2a5e: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:38.362843 18604 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e6f0d14ce4724d63a0d9e4b7805d2a5e: No bootstrap required, opened a new log
I20260812 06:19:38.363288 18604 raft_consensus.cc:359] T 00000000000000000000000000000000 P e6f0d14ce4724d63a0d9e4b7805d2a5e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e6f0d14ce4724d63a0d9e4b7805d2a5e" member_type: VOTER }
I20260812 06:19:38.363412 18604 raft_consensus.cc:385] T 00000000000000000000000000000000 P e6f0d14ce4724d63a0d9e4b7805d2a5e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:38.363466 18604 raft_consensus.cc:740] T 00000000000000000000000000000000 P e6f0d14ce4724d63a0d9e4b7805d2a5e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e6f0d14ce4724d63a0d9e4b7805d2a5e, State: Initialized, Role: FOLLOWER
I20260812 06:19:38.363648 18604 consensus_queue.cc:260] T 00000000000000000000000000000000 P e6f0d14ce4724d63a0d9e4b7805d2a5e [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: "e6f0d14ce4724d63a0d9e4b7805d2a5e" member_type: VOTER }
I20260812 06:19:38.363744 18604 raft_consensus.cc:399] T 00000000000000000000000000000000 P e6f0d14ce4724d63a0d9e4b7805d2a5e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:38.363791 18604 raft_consensus.cc:493] T 00000000000000000000000000000000 P e6f0d14ce4724d63a0d9e4b7805d2a5e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:38.363847 18604 raft_consensus.cc:3060] T 00000000000000000000000000000000 P e6f0d14ce4724d63a0d9e4b7805d2a5e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:38.364595 18604 raft_consensus.cc:515] T 00000000000000000000000000000000 P e6f0d14ce4724d63a0d9e4b7805d2a5e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e6f0d14ce4724d63a0d9e4b7805d2a5e" member_type: VOTER }
I20260812 06:19:38.364766 18604 leader_election.cc:304] T 00000000000000000000000000000000 P e6f0d14ce4724d63a0d9e4b7805d2a5e [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: e6f0d14ce4724d63a0d9e4b7805d2a5e; no voters: 
I20260812 06:19:38.364986 18604 leader_election.cc:290] T 00000000000000000000000000000000 P e6f0d14ce4724d63a0d9e4b7805d2a5e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:38.365190 18609 raft_consensus.cc:2804] T 00000000000000000000000000000000 P e6f0d14ce4724d63a0d9e4b7805d2a5e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:38.365474 18609 raft_consensus.cc:697] T 00000000000000000000000000000000 P e6f0d14ce4724d63a0d9e4b7805d2a5e [term 1 LEADER]: Becoming Leader. State: Replica: e6f0d14ce4724d63a0d9e4b7805d2a5e, State: Running, Role: LEADER
I20260812 06:19:38.365499 18604 sys_catalog.cc:565] T 00000000000000000000000000000000 P e6f0d14ce4724d63a0d9e4b7805d2a5e [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:38.365643 18609 consensus_queue.cc:237] T 00000000000000000000000000000000 P e6f0d14ce4724d63a0d9e4b7805d2a5e [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: "e6f0d14ce4724d63a0d9e4b7805d2a5e" member_type: VOTER }
I20260812 06:19:38.366140 18610 sys_catalog.cc:455] T 00000000000000000000000000000000 P e6f0d14ce4724d63a0d9e4b7805d2a5e [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "e6f0d14ce4724d63a0d9e4b7805d2a5e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e6f0d14ce4724d63a0d9e4b7805d2a5e" member_type: VOTER } }
I20260812 06:19:38.366181 18611 sys_catalog.cc:455] T 00000000000000000000000000000000 P e6f0d14ce4724d63a0d9e4b7805d2a5e [sys.catalog]: SysCatalogTable state changed. Reason: New leader e6f0d14ce4724d63a0d9e4b7805d2a5e. Latest consensus state: current_term: 1 leader_uuid: "e6f0d14ce4724d63a0d9e4b7805d2a5e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e6f0d14ce4724d63a0d9e4b7805d2a5e" member_type: VOTER } }
I20260812 06:19:38.366269 18610 sys_catalog.cc:458] T 00000000000000000000000000000000 P e6f0d14ce4724d63a0d9e4b7805d2a5e [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:38.366287 18611 sys_catalog.cc:458] T 00000000000000000000000000000000 P e6f0d14ce4724d63a0d9e4b7805d2a5e [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:38.366596 18619 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:38.367444 18619 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:38.367622 18300 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:38.369477 18619 catalog_manager.cc:1383] Generated new cluster ID: a7e81ac35656495f993eb068b56e1b33
I20260812 06:19:38.369546 18619 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:38.378253 18619 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:38.378813 18619 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:38.384135 18619 catalog_manager.cc:6092] T 00000000000000000000000000000000 P e6f0d14ce4724d63a0d9e4b7805d2a5e: Generated new TSK 0
I20260812 06:19:38.384327 18619 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:38.400430 18300 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:19:38.402770 18300 server_base.cc:1061] running on GCE node
W20260812 06:19:38.402741 18633 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:19:38.402742 18632 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:38.402760 18635 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:38.403182 18300 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:38.403236 18300 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:38.403254 18300 hybrid_clock.cc:648] HybridClock initialized: now 1786515578403254 us; error 0 us; skew 500 ppm
I20260812 06:19:38.404116 18300 webserver.cc:533] Webserver started at http://127.17.223.1:35827/ using document root <none> and password file <none>
I20260812 06:19:38.404269 18300 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:38.404317 18300 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:38.404371 18300 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:38.404736 18300 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root/instance:
uuid: "ae7a25a9ad2d49188517ee51325dfe6f"
format_stamp: "Formatted at 2026-08-12 06:19:38 on dist-test-slave-mn4r"
I20260812 06:19:38.406248 18300 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:38.407210 18642 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:38.407522 18300 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:38.407593 18300 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root
uuid: "ae7a25a9ad2d49188517ee51325dfe6f"
format_stamp: "Formatted at 2026-08-12 06:19:38 on dist-test-slave-mn4r"
I20260812 06:19:38.407677 18300 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:38.412670 18300 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:38.413036 18300 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:38.413331 18300 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:38.413797 18300 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:38.413836 18300 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:38.413867 18300 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:38.413882 18300 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:38.418917 18300 rpc_server.cc:307] RPC server started. Bound to: 127.17.223.1:35073
I20260812 06:19:38.419185 18721 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.17.223.1:35073 every 8 connection(s)
I20260812 06:19:38.427798 18722 heartbeater.cc:344] Connected to a master server at 127.17.223.62:33109
I20260812 06:19:38.427932 18722 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:38.428226 18722 heartbeater.cc:507] Master 127.17.223.62:33109 requested a full tablet report, sending...
I20260812 06:19:38.428970 18564 ts_manager.cc:194] Registered new tserver with Master: ae7a25a9ad2d49188517ee51325dfe6f (127.17.223.1:35073)
I20260812 06:19:38.429557 18300 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.009999524s
I20260812 06:19:38.429802 18564 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:41922
I20260812 06:19:38.437033 18564 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:41932:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:38.445958 18679 tablet_service.cc:1511] Processing CreateTablet for tablet 1021477a9bea4642a2654016f3030215 (DEFAULT_TABLE table=heavy-update-compaction-test [id=c4c0876976834d1aa76039310d8b1137]), partition=
I20260812 06:19:38.446341 18679 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 1021477a9bea4642a2654016f3030215. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:38.448568 18736 tablet_bootstrap.cc:492] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Bootstrap starting.
I20260812 06:19:38.449424 18736 tablet_bootstrap.cc:654] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:38.450654 18736 tablet_bootstrap.cc:492] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: No bootstrap required, opened a new log
I20260812 06:19:38.450766 18736 ts_tablet_manager.cc:1403] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:38.451345 18736 raft_consensus.cc:359] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ae7a25a9ad2d49188517ee51325dfe6f" member_type: VOTER last_known_addr { host: "127.17.223.1" port: 35073 } }
I20260812 06:19:38.451506 18736 raft_consensus.cc:385] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:38.451561 18736 raft_consensus.cc:740] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ae7a25a9ad2d49188517ee51325dfe6f, State: Initialized, Role: FOLLOWER
I20260812 06:19:38.451730 18736 consensus_queue.cc:260] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f [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: "ae7a25a9ad2d49188517ee51325dfe6f" member_type: VOTER last_known_addr { host: "127.17.223.1" port: 35073 } }
I20260812 06:19:38.451853 18736 raft_consensus.cc:399] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:38.451903 18736 raft_consensus.cc:493] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:38.451957 18736 raft_consensus.cc:3060] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:38.452752 18736 raft_consensus.cc:515] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ae7a25a9ad2d49188517ee51325dfe6f" member_type: VOTER last_known_addr { host: "127.17.223.1" port: 35073 } }
I20260812 06:19:38.452912 18736 leader_election.cc:304] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f [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: ae7a25a9ad2d49188517ee51325dfe6f; no voters: 
I20260812 06:19:38.453155 18736 leader_election.cc:290] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:38.453293 18738 raft_consensus.cc:2804] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:38.453521 18736 ts_tablet_manager.cc:1434] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:38.453552 18722 heartbeater.cc:499] Master 127.17.223.62:33109 was elected leader, sending a full tablet report...
I20260812 06:19:38.453553 18738 raft_consensus.cc:697] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f [term 1 LEADER]: Becoming Leader. State: Replica: ae7a25a9ad2d49188517ee51325dfe6f, State: Running, Role: LEADER
I20260812 06:19:38.453761 18738 consensus_queue.cc:237] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f [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: "ae7a25a9ad2d49188517ee51325dfe6f" member_type: VOTER last_known_addr { host: "127.17.223.1" port: 35073 } }
I20260812 06:19:38.455194 18564 catalog_manager.cc:5719] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f reported cstate change: term changed from 0 to 1, leader changed from <none> to ae7a25a9ad2d49188517ee51325dfe6f (127.17.223.1). New cstate: current_term: 1 leader_uuid: "ae7a25a9ad2d49188517ee51325dfe6f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ae7a25a9ad2d49188517ee51325dfe6f" member_type: VOTER last_known_addr { host: "127.17.223.1" port: 35073 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:38.517024 18300 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.013s	sys 0.009s
I20260812 06:19:38.670150 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushMRSOp(1021477a9bea4642a2654016f3030215): perf score=19.054940
I20260812 06:19:38.823405 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushMRSOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.153s	user 0.114s	sys 0.036s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":192,"dirs.run_wall_time_us":887,"drs_written":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38744,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":756,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":1536,"update_count":1500}
I20260812 06:19:38.824131 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling LogGCOp(1021477a9bea4642a2654016f3030215): free 20743880 bytes of WAL
I20260812 06:19:38.824422 18648 log_reader.cc:385] T 1021477a9bea4642a2654016f3030215: removed 2 log segments from log reader
I20260812 06:19:38.824470 18648 log.cc:1079] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/1021477a9bea4642a2654016f3030215/wal-000000001 (ops 1-6)
I20260812 06:19:38.824503 18648 log.cc:1079] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/1021477a9bea4642a2654016f3030215/wal-000000002 (ops 7-11)
I20260812 06:19:38.828845 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: LogGCOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:38.829317 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=2.188937
I20260812 06:19:38.845043 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5460,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.845661 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling UndoDeltaBlockGCOp(1021477a9bea4642a2654016f3030215): 16411393 bytes on disk
I20260812 06:19:38.846113 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: UndoDeltaBlockGCOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4}
I20260812 06:19:38.846668 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling MajorDeltaCompactionOp(1021477a9bea4642a2654016f3030215): perf score=1.000000
I20260812 06:19:38.999718 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: MajorDeltaCompactionOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.153s	user 0.093s	sys 0.059s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":487,"lbm_read_time_us":11323,"lbm_reads_lt_1ms":460,"lbm_write_time_us":26171,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":23552,"thread_start_us":333,"threads_started":5,"update_count":2000}
I20260812 06:19:39.000379 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=10.126437
I20260812 06:19:39.045440 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.045s	user 0.009s	sys 0.032s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13988,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:39.046159 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=2.188937
I20260812 06:19:39.063246 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.017s	user 0.013s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6234,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:39.063810 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling MajorDeltaCompactionOp(1021477a9bea4642a2654016f3030215): perf score=1.000000
I20260812 06:19:39.212172 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: MajorDeltaCompactionOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.148s	user 0.094s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":410,"lbm_read_time_us":11209,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23147,"lbm_writes_lt_1ms":443,"mutex_wait_us":95,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:39.212772 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=10.126437
I20260812 06:19:39.256541 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.044s	user 0.017s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20867,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:19:39.257162 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=2.188937
I20260812 06:19:39.278061 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.021s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6751,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:39.278620 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling MajorDeltaCompactionOp(1021477a9bea4642a2654016f3030215): perf score=1.000000
I20260812 06:19:39.412827 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: MajorDeltaCompactionOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.134s	user 0.085s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":663,"lbm_read_time_us":10779,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26448,"lbm_writes_lt_1ms":443,"mutex_wait_us":286,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:19:39.413492 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=10.126437
I20260812 06:19:39.451344 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.038s	user 0.013s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14301,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:39.451948 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=2.188937
I20260812 06:19:39.468366 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.016s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6152,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:39.468950 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling MajorDeltaCompactionOp(1021477a9bea4642a2654016f3030215): perf score=1.000000
I20260812 06:19:39.595750 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: MajorDeltaCompactionOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.127s	user 0.108s	sys 0.018s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1071,"lbm_read_time_us":9393,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26018,"lbm_writes_lt_1ms":443,"mutex_wait_us":291,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6144,"update_count":2000}
I20260812 06:19:39.596342 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=10.126437
I20260812 06:19:39.642735 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.046s	user 0.010s	sys 0.033s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15062,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:39.643323 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=2.188937
I20260812 06:19:39.654312 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4298,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:39.654791 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling MajorDeltaCompactionOp(1021477a9bea4642a2654016f3030215): perf score=1.000000
I20260812 06:19:39.812196 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: MajorDeltaCompactionOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.157s	user 0.117s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":810,"lbm_read_time_us":11088,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26084,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6272,"update_count":2000}
I20260812 06:19:39.812912 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=10.126437
I20260812 06:19:39.858322 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.045s	user 0.022s	sys 0.023s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18878,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:39.859169 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=2.188937
I20260812 06:19:39.875592 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.016s	user 0.005s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5989,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:39.876335 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling MajorDeltaCompactionOp(1021477a9bea4642a2654016f3030215): perf score=1.000000
I20260812 06:19:40.013135 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: MajorDeltaCompactionOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.136s	user 0.123s	sys 0.013s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1353,"lbm_read_time_us":10526,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25875,"lbm_writes_lt_1ms":443,"mutex_wait_us":396,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7168,"update_count":2000}
I20260812 06:19:40.013751 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=10.126437
I20260812 06:19:40.058238 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.044s	user 0.019s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17214,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:40.058728 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=2.188937
I20260812 06:19:40.070887 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4486,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.071642 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushMRSOp(1021477a9bea4642a2654016f3030215): perf score=1.000000
I20260812 06:19:40.100148 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushMRSOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.028s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":92,"dirs.run_cpu_time_us":241,"dirs.run_wall_time_us":1308,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1542,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:40.100744 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling LogGCOp(1021477a9bea4642a2654016f3030215): free 111786258 bytes of WAL
I20260812 06:19:40.100965 18648 log_reader.cc:385] T 1021477a9bea4642a2654016f3030215: removed 11 log segments from log reader
I20260812 06:19:40.101032 18648 log.cc:1079] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/1021477a9bea4642a2654016f3030215/wal-000000003 (ops 12-16)
I20260812 06:19:40.101090 18648 log.cc:1079] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/1021477a9bea4642a2654016f3030215/wal-000000004 (ops 17-21)
I20260812 06:19:40.101151 18648 log.cc:1079] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/1021477a9bea4642a2654016f3030215/wal-000000005 (ops 22-26)
I20260812 06:19:40.101191 18648 log.cc:1079] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/1021477a9bea4642a2654016f3030215/wal-000000006 (ops 27-31)
I20260812 06:19:40.101229 18648 log.cc:1079] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/1021477a9bea4642a2654016f3030215/wal-000000007 (ops 32-36)
I20260812 06:19:40.101265 18648 log.cc:1079] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/1021477a9bea4642a2654016f3030215/wal-000000008 (ops 37-40)
I20260812 06:19:40.101301 18648 log.cc:1079] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/1021477a9bea4642a2654016f3030215/wal-000000009 (ops 41-45)
I20260812 06:19:40.101338 18648 log.cc:1079] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/1021477a9bea4642a2654016f3030215/wal-000000010 (ops 46-50)
I20260812 06:19:40.101374 18648 log.cc:1079] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/1021477a9bea4642a2654016f3030215/wal-000000011 (ops 51-55)
I20260812 06:19:40.101410 18648 log.cc:1079] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/1021477a9bea4642a2654016f3030215/wal-000000012 (ops 56-60)
I20260812 06:19:40.101445 18648 log.cc:1079] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/1021477a9bea4642a2654016f3030215/wal-000000013 (ops 61-64)
I20260812 06:19:40.127278 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: LogGCOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:19:40.127755 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling UndoDeltaBlockGCOp(1021477a9bea4642a2654016f3030215): 447 bytes on disk
I20260812 06:19:40.128202 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: UndoDeltaBlockGCOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4}
I20260812 06:19:40.128659 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=3.181125
I20260812 06:19:40.143244 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.014s	user 0.004s	sys 0.007s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":4502,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:40.143710 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=2.188937
I20260812 06:19:40.153971 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3879,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:40.154557 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling MajorDeltaCompactionOp(1021477a9bea4642a2654016f3030215): perf score=1.000000
I20260812 06:19:40.334412 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: MajorDeltaCompactionOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.180s	user 0.116s	sys 0.064s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877325,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":472,"lbm_read_time_us":13920,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32921,"lbm_writes_lt_1ms":643,"mutex_wait_us":58,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3584,"thread_start_us":84,"threads_started":1,"update_count":3000}
I20260812 06:19:40.334982 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=14.095187
I20260812 06:19:40.378716 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.043s	user 0.031s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18849,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:40.379315 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=2.188937
I20260812 06:19:40.395157 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5830,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.395913 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling MajorDeltaCompactionOp(1021477a9bea4642a2654016f3030215): perf score=1.000000
I20260812 06:19:40.556267 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: MajorDeltaCompactionOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.160s	user 0.118s	sys 0.041s 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":234,"lbm_read_time_us":11032,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30297,"lbm_writes_lt_1ms":543,"mutex_wait_us":62,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6912,"update_count":2500}
I20260812 06:19:40.557070 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=12.110812
I20260812 06:19:40.595902 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.039s	user 0.021s	sys 0.015s Metrics: {"bytes_written":13661282,"delete_count":0,"lbm_write_time_us":16970,"lbm_writes_lt_1ms":336,"reinsert_count":0,"update_count":1665}
I20260812 06:19:40.596429 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=1.196750
I20260812 06:19:40.621800 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.025s	user 0.007s	sys 0.003s Metrics: {"bytes_written":2748830,"delete_count":0,"lbm_write_time_us":4558,"lbm_writes_lt_1ms":70,"reinsert_count":0,"update_count":335}
I20260812 06:19:40.622335 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=2.188937
I20260812 06:19:40.634403 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4098,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.635164 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling MajorDeltaCompactionOp(1021477a9bea4642a2654016f3030215): perf score=1.000000
I20260812 06:19:40.811555 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: MajorDeltaCompactionOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.176s	user 0.132s	sys 0.044s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774771,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":733,"lbm_read_time_us":12413,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30630,"lbm_writes_lt_1ms":543,"mutex_wait_us":308,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":45440,"update_count":2500}
I20260812 06:19:40.812218 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=14.095187
I20260812 06:19:40.860581 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.048s	user 0.018s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21413,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:40.861142 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling MajorDeltaCompactionOp(1021477a9bea4642a2654016f3030215): perf score=1.000000
I20260812 06:19:41.009042 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: MajorDeltaCompactionOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.148s	user 0.082s	sys 0.063s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1692,"lbm_read_time_us":12055,"lbm_reads_lt_1ms":463,"lbm_write_time_us":23162,"lbm_writes_lt_1ms":443,"mutex_wait_us":445,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":2000}
I20260812 06:19:41.009689 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=11.118625
I20260812 06:19:41.043609 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.034s	user 0.017s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14326,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:41.044281 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=2.188937
I20260812 06:19:41.071597 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.027s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5166,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:41.072220 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=2.188937
I20260812 06:19:41.083207 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4039,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.083882 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling MajorDeltaCompactionOp(1021477a9bea4642a2654016f3030215): perf score=1.000000
I20260812 06:19:41.281637 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: MajorDeltaCompactionOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.198s	user 0.135s	sys 0.053s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1104,"lbm_read_time_us":10941,"lbm_reads_lt_1ms":573,"lbm_write_time_us":36054,"lbm_writes_lt_1ms":543,"mutex_wait_us":312,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16768,"update_count":2500}
I20260812 06:19:41.282378 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=14.095187
I20260812 06:19:41.331239 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.049s	user 0.021s	sys 0.026s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23687,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:41.331851 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=2.188937
I20260812 06:19:41.348173 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.016s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6045,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.348770 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling MajorDeltaCompactionOp(1021477a9bea4642a2654016f3030215): perf score=1.000000
I20260812 06:19:41.511411 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: MajorDeltaCompactionOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.162s	user 0.126s	sys 0.032s 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":772,"lbm_read_time_us":13234,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31783,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":2500}
I20260812 06:19:41.511996 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=11.118625
I20260812 06:19:41.550344 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.038s	user 0.035s	sys 0.003s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":16679,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:41.550985 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=2.188937
I20260812 06:19:41.578939 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.028s	user 0.008s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5499,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:41.579674 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=2.188937
I20260812 06:19:41.590659 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.011s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4162,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.591182 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushMRSOp(1021477a9bea4642a2654016f3030215): perf score=1.000000
I20260812 06:19:41.625444 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushMRSOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.034s	user 0.026s	sys 0.005s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":89,"dirs.run_cpu_time_us":348,"dirs.run_wall_time_us":1639,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2415,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:41.626243 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling LogGCOp(1021477a9bea4642a2654016f3030215): free 129320454 bytes of WAL
I20260812 06:19:41.626473 18648 log_reader.cc:385] T 1021477a9bea4642a2654016f3030215: removed 13 log segments from log reader
I20260812 06:19:41.626516 18648 log.cc:1079] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/1021477a9bea4642a2654016f3030215/wal-000000014 (ops 65-69)
I20260812 06:19:41.626545 18648 log.cc:1079] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/1021477a9bea4642a2654016f3030215/wal-000000015 (ops 70-74)
I20260812 06:19:41.626616 18648 log.cc:1079] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/1021477a9bea4642a2654016f3030215/wal-000000016 (ops 75-79)
I20260812 06:19:41.626650 18648 log.cc:1079] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/1021477a9bea4642a2654016f3030215/wal-000000017 (ops 80-84)
I20260812 06:19:41.626708 18648 log.cc:1079] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/1021477a9bea4642a2654016f3030215/wal-000000018 (ops 85-89)
I20260812 06:19:41.626754 18648 log.cc:1079] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/1021477a9bea4642a2654016f3030215/wal-000000019 (ops 90-94)
I20260812 06:19:41.626780 18648 log.cc:1079] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/1021477a9bea4642a2654016f3030215/wal-000000020 (ops 95-99)
I20260812 06:19:41.626822 18648 log.cc:1079] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/1021477a9bea4642a2654016f3030215/wal-000000021 (ops 100-104)
I20260812 06:19:41.626861 18648 log.cc:1079] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/1021477a9bea4642a2654016f3030215/wal-000000022 (ops 105-108)
I20260812 06:19:41.626900 18648 log.cc:1079] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/1021477a9bea4642a2654016f3030215/wal-000000023 (ops 109-113)
I20260812 06:19:41.626946 18648 log.cc:1079] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/1021477a9bea4642a2654016f3030215/wal-000000024 (ops 114-118)
I20260812 06:19:41.626986 18648 log.cc:1079] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/1021477a9bea4642a2654016f3030215/wal-000000025 (ops 119-122)
I20260812 06:19:41.627024 18648 log.cc:1079] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/1021477a9bea4642a2654016f3030215/wal-000000026 (ops 123-127)
I20260812 06:19:41.654264 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: LogGCOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.028s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:19:41.654788 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling UndoDeltaBlockGCOp(1021477a9bea4642a2654016f3030215): 482 bytes on disk
I20260812 06:19:41.655278 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: UndoDeltaBlockGCOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:19:41.655817 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=2.188937
I20260812 06:19:41.676730 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.021s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6422,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.677223 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=2.188937
I20260812 06:19:41.702011 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.025s	user 0.010s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3938,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.702625 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling MajorDeltaCompactionOp(1021477a9bea4642a2654016f3030215): perf score=1.000000
I20260812 06:19:41.961170 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: MajorDeltaCompactionOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.258s	user 0.156s	sys 0.097s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979863,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":220,"lbm_read_time_us":17934,"lbm_reads_lt_1ms":775,"lbm_write_time_us":43105,"lbm_writes_lt_1ms":743,"mutex_wait_us":52,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":13440,"thread_start_us":92,"threads_started":1,"update_count":3500}
I20260812 06:19:41.962031 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=18.063937
I20260812 06:19:42.025872 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.063s	user 0.030s	sys 0.029s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":29988,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:19:42.026428 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=2.188937
I20260812 06:19:42.040699 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.014s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5336,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.041450 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling MajorDeltaCompactionOp(1021477a9bea4642a2654016f3030215): perf score=1.000000
I20260812 06:19:42.254281 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: MajorDeltaCompactionOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.213s	user 0.130s	sys 0.083s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":261,"lbm_read_time_us":15494,"lbm_reads_lt_1ms":664,"lbm_write_time_us":34079,"lbm_writes_lt_1ms":643,"mutex_wait_us":20,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":3000}
I20260812 06:19:42.255010 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=14.095187
I20260812 06:19:42.313547 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.058s	user 0.028s	sys 0.026s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26617,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:42.314340 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=3.181125
I20260812 06:19:42.337316 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.023s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":5238,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:42.337993 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=2.188937
I20260812 06:19:42.349607 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4247,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:42.350284 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling MajorDeltaCompactionOp(1021477a9bea4642a2654016f3030215): perf score=1.000000
I20260812 06:19:42.565900 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: MajorDeltaCompactionOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.215s	user 0.137s	sys 0.076s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877207,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":932,"lbm_read_time_us":13709,"lbm_reads_lt_1ms":673,"lbm_write_time_us":38354,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":642,"mutex_wait_us":352,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":71296,"update_count":3000}
I20260812 06:19:42.566751 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=14.095187
I20260812 06:19:42.620726 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.054s	user 0.020s	sys 0.031s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23916,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:42.621268 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=2.188937
I20260812 06:19:42.637684 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6035,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.638268 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling MajorDeltaCompactionOp(1021477a9bea4642a2654016f3030215): perf score=1.000000
I20260812 06:19:42.815809 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: MajorDeltaCompactionOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.177s	user 0.110s	sys 0.067s 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":447,"lbm_read_time_us":12964,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32781,"lbm_writes_lt_1ms":543,"mutex_wait_us":95,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":2500}
I20260812 06:19:42.816566 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=14.095187
I20260812 06:19:42.873266 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.056s	user 0.023s	sys 0.030s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24373,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:42.873883 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=2.188937
I20260812 06:19:42.891290 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.017s	user 0.007s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6894,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.891968 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling MajorDeltaCompactionOp(1021477a9bea4642a2654016f3030215): perf score=1.000000
I20260812 06:19:43.103797 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: MajorDeltaCompactionOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.212s	user 0.119s	sys 0.083s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":234,"lbm_read_time_us":14303,"lbm_reads_lt_1ms":568,"lbm_write_time_us":35179,"lbm_writes_lt_1ms":543,"mutex_wait_us":48,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:19:43.104399 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=14.095187
I20260812 06:19:43.175846 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.070s	user 0.031s	sys 0.035s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26432,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:43.176704 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=2.188937
I20260812 06:19:43.194914 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.018s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6987,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.195561 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushMRSOp(1021477a9bea4642a2654016f3030215): perf score=1.000000
I20260812 06:19:43.234871 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushMRSOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.039s	user 0.030s	sys 0.006s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":88,"dirs.run_cpu_time_us":256,"dirs.run_wall_time_us":1703,"drs_written":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1629,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:43.235605 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling LogGCOp(1021477a9bea4642a2654016f3030215): free 121006745 bytes of WAL
I20260812 06:19:43.235846 18648 log_reader.cc:385] T 1021477a9bea4642a2654016f3030215: removed 12 log segments from log reader
I20260812 06:19:43.235898 18648 log.cc:1079] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/1021477a9bea4642a2654016f3030215/wal-000000027 (ops 128-132)
I20260812 06:19:43.235927 18648 log.cc:1079] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/1021477a9bea4642a2654016f3030215/wal-000000028 (ops 133-137)
I20260812 06:19:43.235980 18648 log.cc:1079] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/1021477a9bea4642a2654016f3030215/wal-000000029 (ops 138-142)
I20260812 06:19:43.236027 18648 log.cc:1079] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/1021477a9bea4642a2654016f3030215/wal-000000030 (ops 143-147)
I20260812 06:19:43.236045 18648 log.cc:1079] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/1021477a9bea4642a2654016f3030215/wal-000000031 (ops 148-152)
I20260812 06:19:43.236099 18648 log.cc:1079] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/1021477a9bea4642a2654016f3030215/wal-000000032 (ops 153-157)
I20260812 06:19:43.236156 18648 log.cc:1079] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/1021477a9bea4642a2654016f3030215/wal-000000033 (ops 158-162)
I20260812 06:19:43.236194 18648 log.cc:1079] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/1021477a9bea4642a2654016f3030215/wal-000000034 (ops 163-166)
I20260812 06:19:43.236231 18648 log.cc:1079] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/1021477a9bea4642a2654016f3030215/wal-000000035 (ops 167-171)
I20260812 06:19:43.236300 18648 log.cc:1079] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/1021477a9bea4642a2654016f3030215/wal-000000036 (ops 172-176)
I20260812 06:19:43.236356 18648 log.cc:1079] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/1021477a9bea4642a2654016f3030215/wal-000000037 (ops 177-181)
I20260812 06:19:43.236403 18648 log.cc:1079] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: Deleting log segment in path: /tmp/dist-test-task3oa0G_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515572588936-18300-0/minicluster-data/ts-0-root/wals/1021477a9bea4642a2654016f3030215/wal-000000038 (ops 182-186)
I20260812 06:19:43.264896 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: LogGCOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.029s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:43.265419 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=3.181125
I20260812 06:19:43.286589 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.021s	user 0.012s	sys 0.003s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":5973,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:43.287142 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling UndoDeltaBlockGCOp(1021477a9bea4642a2654016f3030215): 462 bytes on disk
I20260812 06:19:43.287593 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: UndoDeltaBlockGCOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:19:43.288146 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=2.188937
I20260812 06:19:43.298328 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3623,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:43.299176 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling MajorDeltaCompactionOp(1021477a9bea4642a2654016f3030215): perf score=1.000000
I20260812 06:19:43.558125 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: MajorDeltaCompactionOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.259s	user 0.185s	sys 0.066s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979738,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1222,"lbm_read_time_us":19073,"lbm_reads_lt_1ms":774,"lbm_write_time_us":45688,"lbm_writes_lt_1ms":743,"mutex_wait_us":335,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":29568,"thread_start_us":83,"threads_started":1,"update_count":3500}
I20260812 06:19:43.558967 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=18.063937
I20260812 06:19:43.618803 18300 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.102s	user 1.851s	sys 0.168s
I20260812 06:19:43.623152 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.064s	user 0.030s	sys 0.025s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":25115,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:43.623721 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215): perf score=2.188937
I20260812 06:19:43.635468 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: FlushDeltaMemStoresOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.011s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4807,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":500}
I20260812 06:19:43.636023 18724 maintenance_manager.cc:419] P ae7a25a9ad2d49188517ee51325dfe6f: Scheduling MajorDeltaCompactionOp(1021477a9bea4642a2654016f3030215): perf score=1.000000
I20260812 06:19:43.682045 18300 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.063s	user 0.001s	sys 0.000s
I20260812 06:19:43.682642 18300 tablet_server.cc:179] TabletServer@127.17.223.1:0 shutting down...
I20260812 06:19:43.797201 18648 maintenance_manager.cc:643] P ae7a25a9ad2d49188517ee51325dfe6f: MajorDeltaCompactionOp(1021477a9bea4642a2654016f3030215) complete. Timing: real 0.161s	user 0.096s	sys 0.064s Metrics: {"cfile_cache_hit":346,"cfile_cache_hit_bytes":14155477,"cfile_cache_miss":286,"cfile_cache_miss_bytes":14721626,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":345,"lbm_read_time_us":6323,"lbm_reads_lt_1ms":318,"lbm_write_time_us":31323,"lbm_writes_lt_1ms":643,"mutex_wait_us":45,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":88192,"update_count":3000}
I20260812 06:19:43.798128 18300 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:43.798400 18300 tablet_replica.cc:333] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f: stopping tablet replica
I20260812 06:19:43.798588 18300 raft_consensus.cc:2243] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:43.798810 18300 raft_consensus.cc:2272] T 1021477a9bea4642a2654016f3030215 P ae7a25a9ad2d49188517ee51325dfe6f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:43.803308 18300 tablet_server.cc:196] TabletServer@127.17.223.1:0 shutdown complete.
I20260812 06:19:43.855106 18300 master.cc:562] Master@127.17.223.62:33109 shutting down...
I20260812 06:19:43.859200 18300 raft_consensus.cc:2243] T 00000000000000000000000000000000 P e6f0d14ce4724d63a0d9e4b7805d2a5e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:43.859402 18300 raft_consensus.cc:2272] T 00000000000000000000000000000000 P e6f0d14ce4724d63a0d9e4b7805d2a5e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:43.859458 18300 tablet_replica.cc:333] T 00000000000000000000000000000000 P e6f0d14ce4724d63a0d9e4b7805d2a5e: stopping tablet replica
I20260812 06:19:43.871959 18300 master.cc:584] Master@127.17.223.62:33109 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5650 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11369 ms total)

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