[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:18:12.358696 14788 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.14.113.62:33219
I20260812 06:18:12.359762 14788 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:18:12.360424 14788 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:12.367569 14798 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:12.367538 14796 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:12.367908 14788 server_base.cc:1061] running on GCE node
W20260812 06:18:12.367935 14795 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:12.368458 14788 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:12.368584 14788 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:12.368649 14788 hybrid_clock.cc:648] HybridClock initialized: now 1786515492368646 us; error 0 us; skew 500 ppm
I20260812 06:18:12.370519 14788 webserver.cc:533] Webserver started at http://127.14.113.62:39659/ using document root <none> and password file <none>
I20260812 06:18:12.371095 14788 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:12.371186 14788 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:12.371459 14788 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:12.373198 14788 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/master-0-root/instance:
uuid: "874aed1303074cefaef40f26f97f015a"
format_stamp: "Formatted at 2026-08-12 06:18:12 on dist-test-slave-27sr"
I20260812 06:18:12.376866 14788 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.001s
I20260812 06:18:12.379009 14803 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:12.380051 14788 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.001s
I20260812 06:18:12.380187 14788 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/master-0-root
uuid: "874aed1303074cefaef40f26f97f015a"
format_stamp: "Formatted at 2026-08-12 06:18:12 on dist-test-slave-27sr"
I20260812 06:18:12.380306 14788 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:12.397365 14788 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:12.398077 14788 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:18:12.398293 14788 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:12.406728 14788 rpc_server.cc:307] RPC server started. Bound to: 127.14.113.62:33219
I20260812 06:18:12.406800 14861 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.14.113.62:33219 every 8 connection(s)
I20260812 06:18:12.409193 14862 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:12.414847 14862 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 874aed1303074cefaef40f26f97f015a: Bootstrap starting.
I20260812 06:18:12.417308 14862 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 874aed1303074cefaef40f26f97f015a: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:12.418224 14862 log.cc:826] T 00000000000000000000000000000000 P 874aed1303074cefaef40f26f97f015a: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:12.420070 14862 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 874aed1303074cefaef40f26f97f015a: No bootstrap required, opened a new log
I20260812 06:18:12.422974 14862 raft_consensus.cc:359] T 00000000000000000000000000000000 P 874aed1303074cefaef40f26f97f015a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "874aed1303074cefaef40f26f97f015a" member_type: VOTER }
I20260812 06:18:12.423149 14862 raft_consensus.cc:385] T 00000000000000000000000000000000 P 874aed1303074cefaef40f26f97f015a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:12.423192 14862 raft_consensus.cc:740] T 00000000000000000000000000000000 P 874aed1303074cefaef40f26f97f015a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 874aed1303074cefaef40f26f97f015a, State: Initialized, Role: FOLLOWER
I20260812 06:18:12.423763 14862 consensus_queue.cc:260] T 00000000000000000000000000000000 P 874aed1303074cefaef40f26f97f015a [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: "874aed1303074cefaef40f26f97f015a" member_type: VOTER }
I20260812 06:18:12.423962 14862 raft_consensus.cc:399] T 00000000000000000000000000000000 P 874aed1303074cefaef40f26f97f015a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:12.424032 14862 raft_consensus.cc:493] T 00000000000000000000000000000000 P 874aed1303074cefaef40f26f97f015a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:12.424124 14862 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 874aed1303074cefaef40f26f97f015a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:12.424928 14862 raft_consensus.cc:515] T 00000000000000000000000000000000 P 874aed1303074cefaef40f26f97f015a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "874aed1303074cefaef40f26f97f015a" member_type: VOTER }
I20260812 06:18:12.425339 14862 leader_election.cc:304] T 00000000000000000000000000000000 P 874aed1303074cefaef40f26f97f015a [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: 874aed1303074cefaef40f26f97f015a; no voters: 
I20260812 06:18:12.425640 14862 leader_election.cc:290] T 00000000000000000000000000000000 P 874aed1303074cefaef40f26f97f015a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:12.425812 14865 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 874aed1303074cefaef40f26f97f015a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:12.426079 14865 raft_consensus.cc:697] T 00000000000000000000000000000000 P 874aed1303074cefaef40f26f97f015a [term 1 LEADER]: Becoming Leader. State: Replica: 874aed1303074cefaef40f26f97f015a, State: Running, Role: LEADER
I20260812 06:18:12.426498 14865 consensus_queue.cc:237] T 00000000000000000000000000000000 P 874aed1303074cefaef40f26f97f015a [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: "874aed1303074cefaef40f26f97f015a" member_type: VOTER }
I20260812 06:18:12.426764 14862 sys_catalog.cc:565] T 00000000000000000000000000000000 P 874aed1303074cefaef40f26f97f015a [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:12.428512 14867 sys_catalog.cc:455] T 00000000000000000000000000000000 P 874aed1303074cefaef40f26f97f015a [sys.catalog]: SysCatalogTable state changed. Reason: New leader 874aed1303074cefaef40f26f97f015a. Latest consensus state: current_term: 1 leader_uuid: "874aed1303074cefaef40f26f97f015a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "874aed1303074cefaef40f26f97f015a" member_type: VOTER } }
I20260812 06:18:12.428555 14866 sys_catalog.cc:455] T 00000000000000000000000000000000 P 874aed1303074cefaef40f26f97f015a [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "874aed1303074cefaef40f26f97f015a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "874aed1303074cefaef40f26f97f015a" member_type: VOTER } }
I20260812 06:18:12.428643 14867 sys_catalog.cc:458] T 00000000000000000000000000000000 P 874aed1303074cefaef40f26f97f015a [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:12.428654 14866 sys_catalog.cc:458] T 00000000000000000000000000000000 P 874aed1303074cefaef40f26f97f015a [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:12.429127 14876 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:12.429446 14788 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:12.431622 14876 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:12.436304 14876 catalog_manager.cc:1383] Generated new cluster ID: e436d4f8a4b0456fad2ec34654f46790
I20260812 06:18:12.436376 14876 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:12.449030 14876 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:12.449935 14876 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:12.455456 14876 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 874aed1303074cefaef40f26f97f015a: Generated new TSK 0
I20260812 06:18:12.456171 14876 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:12.462229 14788 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:12.465404 14888 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:12.465569 14887 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:12.465404 14890 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:12.465662 14788 server_base.cc:1061] running on GCE node
I20260812 06:18:12.466034 14788 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:12.466102 14788 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:12.466130 14788 hybrid_clock.cc:648] HybridClock initialized: now 1786515492466128 us; error 0 us; skew 500 ppm
I20260812 06:18:12.467105 14788 webserver.cc:533] Webserver started at http://127.14.113.1:37677/ using document root <none> and password file <none>
I20260812 06:18:12.467290 14788 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:12.467363 14788 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:12.467443 14788 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:12.467855 14788 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/instance:
uuid: "65fe30f48b234e1f946d2dead2a68cc6"
format_stamp: "Formatted at 2026-08-12 06:18:12 on dist-test-slave-27sr"
I20260812 06:18:12.469455 14788 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:12.470507 14895 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:12.470753 14788 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:12.470831 14788 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root
uuid: "65fe30f48b234e1f946d2dead2a68cc6"
format_stamp: "Formatted at 2026-08-12 06:18:12 on dist-test-slave-27sr"
I20260812 06:18:12.470916 14788 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:12.481002 14788 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:12.481477 14788 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:12.482005 14788 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:12.482931 14788 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:12.482982 14788 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:12.483050 14788 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:12.483093 14788 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:12.490023 14788 rpc_server.cc:307] RPC server started. Bound to: 127.14.113.1:41405
I20260812 06:18:12.490056 14975 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.14.113.1:41405 every 8 connection(s)
I20260812 06:18:12.504524 14976 heartbeater.cc:344] Connected to a master server at 127.14.113.62:33219
I20260812 06:18:12.504804 14976 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:12.505345 14976 heartbeater.cc:507] Master 127.14.113.62:33219 requested a full tablet report, sending...
I20260812 06:18:12.506976 14822 ts_manager.cc:194] Registered new tserver with Master: 65fe30f48b234e1f946d2dead2a68cc6 (127.14.113.1:41405)
I20260812 06:18:12.507445 14788 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.016753922s
I20260812 06:18:12.508643 14822 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:59804
I20260812 06:18:12.518358 14822 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:59806:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:12.534322 14931 tablet_service.cc:1511] Processing CreateTablet for tablet 821108b946014e6e8b5033190d4d73b1 (DEFAULT_TABLE table=heavy-update-compaction-test [id=33c1a72c30184642823c7176a9b0c904]), partition=
I20260812 06:18:12.534844 14931 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 821108b946014e6e8b5033190d4d73b1. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:12.537694 14990 tablet_bootstrap.cc:492] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Bootstrap starting.
I20260812 06:18:12.538740 14990 tablet_bootstrap.cc:654] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:12.540092 14990 tablet_bootstrap.cc:492] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: No bootstrap required, opened a new log
I20260812 06:18:12.540210 14990 ts_tablet_manager.cc:1403] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:12.540804 14990 raft_consensus.cc:359] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "65fe30f48b234e1f946d2dead2a68cc6" member_type: VOTER last_known_addr { host: "127.14.113.1" port: 41405 } }
I20260812 06:18:12.540939 14990 raft_consensus.cc:385] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:12.540988 14990 raft_consensus.cc:740] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 65fe30f48b234e1f946d2dead2a68cc6, State: Initialized, Role: FOLLOWER
I20260812 06:18:12.541134 14990 consensus_queue.cc:260] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6 [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: "65fe30f48b234e1f946d2dead2a68cc6" member_type: VOTER last_known_addr { host: "127.14.113.1" port: 41405 } }
I20260812 06:18:12.541267 14990 raft_consensus.cc:399] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:12.541320 14990 raft_consensus.cc:493] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:12.541376 14990 raft_consensus.cc:3060] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:12.542191 14990 raft_consensus.cc:515] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "65fe30f48b234e1f946d2dead2a68cc6" member_type: VOTER last_known_addr { host: "127.14.113.1" port: 41405 } }
I20260812 06:18:12.542358 14990 leader_election.cc:304] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6 [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: 65fe30f48b234e1f946d2dead2a68cc6; no voters: 
I20260812 06:18:12.542649 14990 leader_election.cc:290] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:12.542778 14992 raft_consensus.cc:2804] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:12.543049 14990 ts_tablet_manager.cc:1434] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:12.543381 14992 raft_consensus.cc:697] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6 [term 1 LEADER]: Becoming Leader. State: Replica: 65fe30f48b234e1f946d2dead2a68cc6, State: Running, Role: LEADER
I20260812 06:18:12.543432 14976 heartbeater.cc:499] Master 127.14.113.62:33219 was elected leader, sending a full tablet report...
I20260812 06:18:12.543546 14992 consensus_queue.cc:237] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6 [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: "65fe30f48b234e1f946d2dead2a68cc6" member_type: VOTER last_known_addr { host: "127.14.113.1" port: 41405 } }
I20260812 06:18:12.546634 14822 catalog_manager.cc:5719] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6 reported cstate change: term changed from 0 to 1, leader changed from <none> to 65fe30f48b234e1f946d2dead2a68cc6 (127.14.113.1). New cstate: current_term: 1 leader_uuid: "65fe30f48b234e1f946d2dead2a68cc6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "65fe30f48b234e1f946d2dead2a68cc6" member_type: VOTER last_known_addr { host: "127.14.113.1" port: 41405 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:12.615048 14788 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.061s	user 0.015s	sys 0.013s
I20260812 06:18:12.741307 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushMRSOp(821108b946014e6e8b5033190d4d73b1): perf score=15.086190
I20260812 06:18:12.900589 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushMRSOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.159s	user 0.117s	sys 0.036s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":275,"delete_count":0,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":236,"dirs.run_wall_time_us":895,"drs_written":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41382,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":656,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"thread_start_us":163,"threads_started":1,"update_count":1500}
I20260812 06:18:12.901783 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling UndoDeltaBlockGCOp(821108b946014e6e8b5033190d4d73b1): 12308958 bytes on disk
I20260812 06:18:12.902345 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: UndoDeltaBlockGCOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:18:12.902745 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling MajorDeltaCompactionOp(821108b946014e6e8b5033190d4d73b1): perf score=1.000000
I20260812 06:18:13.026970 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: MajorDeltaCompactionOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.124s	user 0.079s	sys 0.040s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":316,"lbm_read_time_us":6806,"lbm_reads_lt_1ms":359,"lbm_write_time_us":23312,"lbm_writes_lt_1ms":343,"mutex_wait_us":50,"peak_mem_usage":38262756,"reinsert_count":0,"thread_start_us":301,"threads_started":5,"update_count":1500}
I20260812 06:18:13.027462 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling LogGCOp(821108b946014e6e8b5033190d4d73b1): free 11976772 bytes of WAL
I20260812 06:18:13.027782 14901 log_reader.cc:385] T 821108b946014e6e8b5033190d4d73b1: removed 1 log segments from log reader
I20260812 06:18:13.027860 14901 log.cc:1079] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/821108b946014e6e8b5033190d4d73b1/wal-000000001 (ops 1-6)
I20260812 06:18:13.031188 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: LogGCOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.004s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:13.032024 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=10.126437
I20260812 06:18:13.073151 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.041s	user 0.010s	sys 0.026s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15849,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:13.073606 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=2.188937
I20260812 06:18:13.084125 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.010s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3873,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:13.084897 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling MajorDeltaCompactionOp(821108b946014e6e8b5033190d4d73b1): perf score=1.000000
I20260812 06:18:13.204970 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: MajorDeltaCompactionOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.120s	user 0.088s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":281,"lbm_read_time_us":8638,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23269,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:13.205605 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=10.126437
I20260812 06:18:13.258004 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.052s	user 0.021s	sys 0.025s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16724,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:13.258632 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=2.188937
I20260812 06:18:13.270251 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4530,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:13.270746 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling MajorDeltaCompactionOp(821108b946014e6e8b5033190d4d73b1): perf score=1.000000
I20260812 06:18:13.431681 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: MajorDeltaCompactionOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.161s	user 0.108s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1109,"lbm_read_time_us":11299,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24714,"lbm_writes_lt_1ms":443,"mutex_wait_us":362,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2000}
I20260812 06:18:13.432363 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=10.126437
I20260812 06:18:13.481864 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.049s	user 0.026s	sys 0.010s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16716,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:13.482420 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=2.188937
I20260812 06:18:13.493470 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.011s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4183,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:13.494026 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling MajorDeltaCompactionOp(821108b946014e6e8b5033190d4d73b1): perf score=1.000000
I20260812 06:18:13.621603 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: MajorDeltaCompactionOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.127s	user 0.110s	sys 0.018s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":192,"lbm_read_time_us":10231,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23061,"lbm_writes_lt_1ms":443,"mutex_wait_us":35,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2000}
I20260812 06:18:13.622154 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=10.126437
I20260812 06:18:13.664413 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.042s	user 0.035s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16466,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:13.664889 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=2.188937
I20260812 06:18:13.676487 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.011s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4245,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:13.677182 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling MajorDeltaCompactionOp(821108b946014e6e8b5033190d4d73b1): perf score=1.000000
I20260812 06:18:13.801684 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: MajorDeltaCompactionOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.124s	user 0.104s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":324,"lbm_read_time_us":9974,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23482,"lbm_writes_lt_1ms":443,"mutex_wait_us":31,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14592,"update_count":2000}
I20260812 06:18:13.802341 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=10.126437
I20260812 06:18:13.853415 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.051s	user 0.023s	sys 0.023s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15851,"lbm_writes_lt_1ms":303,"mutex_wait_us":2,"reinsert_count":0,"update_count":1500}
I20260812 06:18:13.854177 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=2.188937
I20260812 06:18:13.865885 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4516,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:13.866461 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling MajorDeltaCompactionOp(821108b946014e6e8b5033190d4d73b1): perf score=1.000000
I20260812 06:18:14.016047 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: MajorDeltaCompactionOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.149s	user 0.080s	sys 0.068s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":681,"lbm_read_time_us":10942,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23980,"lbm_writes_lt_1ms":443,"mutex_wait_us":41,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:14.016646 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=10.126437
I20260812 06:18:14.056571 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.040s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17189,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:14.057230 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=2.188937
I20260812 06:18:14.077731 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.020s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5788,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:14.078208 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushMRSOp(821108b946014e6e8b5033190d4d73b1): perf score=1.000000
I20260812 06:18:14.117116 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushMRSOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.039s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1152509,"cfile_init":1,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":281,"dirs.run_wall_time_us":1614,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1697,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:14.118391 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling UndoDeltaBlockGCOp(821108b946014e6e8b5033190d4d73b1): 447 bytes on disk
I20260812 06:18:14.118866 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: UndoDeltaBlockGCOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:18:14.119465 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=3.181125
I20260812 06:18:14.140556 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.021s	user 0.008s	sys 0.011s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4523,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:14.141103 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling LogGCOp(821108b946014e6e8b5033190d4d73b1): free 112692354 bytes of WAL
I20260812 06:18:14.141371 14901 log_reader.cc:385] T 821108b946014e6e8b5033190d4d73b1: removed 11 log segments from log reader
I20260812 06:18:14.141420 14901 log.cc:1079] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/821108b946014e6e8b5033190d4d73b1/wal-000000002 (ops 7-11)
I20260812 06:18:14.141450 14901 log.cc:1079] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/821108b946014e6e8b5033190d4d73b1/wal-000000003 (ops 12-16)
I20260812 06:18:14.141497 14901 log.cc:1079] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/821108b946014e6e8b5033190d4d73b1/wal-000000004 (ops 17-21)
I20260812 06:18:14.141546 14901 log.cc:1079] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/821108b946014e6e8b5033190d4d73b1/wal-000000005 (ops 22-26)
I20260812 06:18:14.141610 14901 log.cc:1079] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/821108b946014e6e8b5033190d4d73b1/wal-000000006 (ops 27-31)
I20260812 06:18:14.141657 14901 log.cc:1079] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/821108b946014e6e8b5033190d4d73b1/wal-000000007 (ops 32-36)
I20260812 06:18:14.141676 14901 log.cc:1079] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/821108b946014e6e8b5033190d4d73b1/wal-000000008 (ops 37-41)
I20260812 06:18:14.141732 14901 log.cc:1079] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/821108b946014e6e8b5033190d4d73b1/wal-000000009 (ops 42-46)
I20260812 06:18:14.141772 14901 log.cc:1079] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/821108b946014e6e8b5033190d4d73b1/wal-000000010 (ops 47-51)
I20260812 06:18:14.141819 14901 log.cc:1079] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/821108b946014e6e8b5033190d4d73b1/wal-000000011 (ops 52-56)
I20260812 06:18:14.141860 14901 log.cc:1079] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/821108b946014e6e8b5033190d4d73b1/wal-000000012 (ops 57-61)
I20260812 06:18:14.168680 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: LogGCOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.027s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:14.169283 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=2.188937
I20260812 06:18:14.181242 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4440,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:14.181731 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling MajorDeltaCompactionOp(821108b946014e6e8b5033190d4d73b1): perf score=1.000000
I20260812 06:18:14.371238 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: MajorDeltaCompactionOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.189s	user 0.133s	sys 0.056s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836363,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":412,"lbm_read_time_us":12922,"lbm_reads_lt_1ms":670,"lbm_write_time_us":33124,"lbm_writes_lt_1ms":643,"mutex_wait_us":55,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9984,"thread_start_us":83,"threads_started":1,"update_count":3000}
I20260812 06:18:14.374281 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=14.095187
I20260812 06:18:14.437923 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.063s	user 0.022s	sys 0.039s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25989,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:18:14.438547 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=2.188937
I20260812 06:18:14.454026 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.015s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4979,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:14.454466 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=2.188937
I20260812 06:18:14.465282 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4121,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:14.465788 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling MajorDeltaCompactionOp(821108b946014e6e8b5033190d4d73b1): perf score=1.000000
I20260812 06:18:14.660641 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: MajorDeltaCompactionOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.195s	user 0.122s	sys 0.072s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836255,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":629,"lbm_read_time_us":14104,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33158,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":20480,"update_count":3000}
I20260812 06:18:14.661239 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=14.095187
I20260812 06:18:14.717892 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.056s	user 0.045s	sys 0.008s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":24081,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:14.718446 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=2.188937
I20260812 06:18:14.729800 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4406,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:14.730520 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling MajorDeltaCompactionOp(821108b946014e6e8b5033190d4d73b1): perf score=1.000000
I20260812 06:18:14.909751 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: MajorDeltaCompactionOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.179s	user 0.104s	sys 0.067s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":833,"lbm_read_time_us":12389,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31291,"lbm_writes_lt_1ms":543,"mutex_wait_us":73,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:18:14.910429 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=14.095187
I20260812 06:18:14.975081 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.064s	user 0.015s	sys 0.046s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24774,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:14.975700 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=2.188937
I20260812 06:18:14.986910 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4267,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:14.987416 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling MajorDeltaCompactionOp(821108b946014e6e8b5033190d4d73b1): perf score=1.000000
I20260812 06:18:15.165603 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: MajorDeltaCompactionOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.178s	user 0.121s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":591,"lbm_read_time_us":15332,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30267,"lbm_writes_lt_1ms":543,"mutex_wait_us":304,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20864,"update_count":2500}
I20260812 06:18:15.166153 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=11.118625
I20260812 06:18:15.212738 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.046s	user 0.031s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18320,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:18:15.213271 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=2.188937
I20260812 06:18:15.232285 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.019s	user 0.002s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4422,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.233017 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=2.188937
I20260812 06:18:15.249006 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5730,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:15.249804 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling MajorDeltaCompactionOp(821108b946014e6e8b5033190d4d73b1): perf score=1.000000
I20260812 06:18:15.449254 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: MajorDeltaCompactionOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.199s	user 0.152s	sys 0.036s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733834,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":717,"lbm_read_time_us":17008,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32401,"lbm_writes_lt_1ms":543,"mutex_wait_us":341,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8320,"update_count":2500}
I20260812 06:18:15.449915 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=14.095187
I20260812 06:18:15.500356 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.050s	user 0.032s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19677,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:15.500844 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=2.188937
I20260812 06:18:15.521739 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.021s	user 0.007s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4642,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.522413 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling MajorDeltaCompactionOp(821108b946014e6e8b5033190d4d73b1): perf score=1.000000
I20260812 06:18:15.720233 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: MajorDeltaCompactionOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.198s	user 0.137s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":647,"lbm_read_time_us":13698,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32299,"lbm_writes_lt_1ms":543,"mutex_wait_us":344,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19456,"update_count":2500}
I20260812 06:18:15.720893 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=14.095187
I20260812 06:18:15.783105 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.062s	user 0.030s	sys 0.029s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":29328,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:18:15.783612 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=2.188937
I20260812 06:18:15.795977 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.012s	user 0.005s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4653,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.796443 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushMRSOp(821108b946014e6e8b5033190d4d73b1): perf score=1.000000
I20260812 06:18:15.838865 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushMRSOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.042s	user 0.032s	sys 0.007s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":86,"dirs.run_cpu_time_us":198,"dirs.run_wall_time_us":1500,"drs_written":1,"lbm_read_time_us":134,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1627,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:15.839737 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling LogGCOp(821108b946014e6e8b5033190d4d73b1): free 137181512 bytes of WAL
I20260812 06:18:15.840166 14901 log_reader.cc:385] T 821108b946014e6e8b5033190d4d73b1: removed 14 log segments from log reader
I20260812 06:18:15.840258 14901 log.cc:1079] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/821108b946014e6e8b5033190d4d73b1/wal-000000013 (ops 62-66)
I20260812 06:18:15.840318 14901 log.cc:1079] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/821108b946014e6e8b5033190d4d73b1/wal-000000014 (ops 67-70)
I20260812 06:18:15.840365 14901 log.cc:1079] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/821108b946014e6e8b5033190d4d73b1/wal-000000015 (ops 71-75)
I20260812 06:18:15.840401 14901 log.cc:1079] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/821108b946014e6e8b5033190d4d73b1/wal-000000016 (ops 76-80)
I20260812 06:18:15.840435 14901 log.cc:1079] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/821108b946014e6e8b5033190d4d73b1/wal-000000017 (ops 81-85)
I20260812 06:18:15.840466 14901 log.cc:1079] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/821108b946014e6e8b5033190d4d73b1/wal-000000018 (ops 86-90)
I20260812 06:18:15.840505 14901 log.cc:1079] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/821108b946014e6e8b5033190d4d73b1/wal-000000019 (ops 91-94)
I20260812 06:18:15.840549 14901 log.cc:1079] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/821108b946014e6e8b5033190d4d73b1/wal-000000020 (ops 95-99)
I20260812 06:18:15.840593 14901 log.cc:1079] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/821108b946014e6e8b5033190d4d73b1/wal-000000021 (ops 100-104)
I20260812 06:18:15.840636 14901 log.cc:1079] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/821108b946014e6e8b5033190d4d73b1/wal-000000022 (ops 105-108)
I20260812 06:18:15.840677 14901 log.cc:1079] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/821108b946014e6e8b5033190d4d73b1/wal-000000023 (ops 109-113)
I20260812 06:18:15.840734 14901 log.cc:1079] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/821108b946014e6e8b5033190d4d73b1/wal-000000024 (ops 114-118)
I20260812 06:18:15.840770 14901 log.cc:1079] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/821108b946014e6e8b5033190d4d73b1/wal-000000025 (ops 119-122)
I20260812 06:18:15.840803 14901 log.cc:1079] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/821108b946014e6e8b5033190d4d73b1/wal-000000026 (ops 123-127)
I20260812 06:18:15.875222 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: LogGCOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.035s	user 0.004s	sys 0.028s Metrics: {}
I20260812 06:18:15.875662 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=3.181125
I20260812 06:18:15.889272 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4506,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:15.889729 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=2.188937
I20260812 06:18:15.899434 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3642,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:15.899994 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling MajorDeltaCompactionOp(821108b946014e6e8b5033190d4d73b1): perf score=1.000000
I20260812 06:18:16.148229 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: MajorDeltaCompactionOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.248s	user 0.134s	sys 0.100s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938778,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":429,"lbm_read_time_us":16898,"lbm_reads_lt_1ms":774,"lbm_write_time_us":37520,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":89,"threads_started":1,"update_count":3500}
I20260812 06:18:16.148766 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=18.063937
I20260812 06:18:16.219683 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.071s	user 0.040s	sys 0.016s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":27224,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:16.220376 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling UndoDeltaBlockGCOp(821108b946014e6e8b5033190d4d73b1): 493 bytes on disk
I20260812 06:18:16.220839 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: UndoDeltaBlockGCOp(821108b946014e6e8b5033190d4d73b1) 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:18:16.221357 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=2.188937
I20260812 06:18:16.233886 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4164,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.234442 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling MajorDeltaCompactionOp(821108b946014e6e8b5033190d4d73b1): perf score=1.000000
I20260812 06:18:16.444375 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: MajorDeltaCompactionOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.210s	user 0.150s	sys 0.059s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836137,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":239,"lbm_read_time_us":15123,"lbm_reads_lt_1ms":672,"lbm_write_time_us":37716,"lbm_writes_lt_1ms":643,"mutex_wait_us":38,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14720,"update_count":3000}
I20260812 06:18:16.445149 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=14.095187
I20260812 06:18:16.490303 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.045s	user 0.030s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20162,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:16.491046 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling MajorDeltaCompactionOp(821108b946014e6e8b5033190d4d73b1): perf score=1.000000
I20260812 06:18:16.657289 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: MajorDeltaCompactionOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.166s	user 0.124s	sys 0.042s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631192,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":164,"lbm_read_time_us":13036,"lbm_reads_lt_1ms":467,"lbm_write_time_us":26938,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2000}
I20260812 06:18:16.658011 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=14.095187
I20260812 06:18:16.709326 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.051s	user 0.033s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22822,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:16.710062 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=2.188937
I20260812 06:18:16.723817 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5370,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.724354 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling MajorDeltaCompactionOp(821108b946014e6e8b5033190d4d73b1): perf score=1.000000
I20260812 06:18:16.936451 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: MajorDeltaCompactionOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.212s	user 0.155s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":337,"lbm_read_time_us":15713,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31717,"lbm_writes_lt_1ms":543,"mutex_wait_us":34,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:16.937266 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=14.095187
I20260812 06:18:16.993147 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.056s	user 0.035s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24753,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:16.993836 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=2.188937
I20260812 06:18:17.006706 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4878,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.007217 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling MajorDeltaCompactionOp(821108b946014e6e8b5033190d4d73b1): perf score=1.000000
I20260812 06:18:17.163655 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: MajorDeltaCompactionOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.156s	user 0.130s	sys 0.021s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":140,"lbm_read_time_us":12326,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30734,"lbm_writes_lt_1ms":543,"mutex_wait_us":33,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2500}
I20260812 06:18:17.164485 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=11.118625
I20260812 06:18:17.197201 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.032s	user 0.020s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13952,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:17.198068 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=2.188937
I20260812 06:18:17.213522 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5459,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:17.214061 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling MajorDeltaCompactionOp(821108b946014e6e8b5033190d4d73b1): perf score=1.000000
I20260812 06:18:17.343544 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: MajorDeltaCompactionOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.129s	user 0.097s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":585,"lbm_read_time_us":7909,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26647,"lbm_writes_lt_1ms":443,"mutex_wait_us":32,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15360,"update_count":2000}
I20260812 06:18:17.345283 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=10.126437
I20260812 06:18:17.384459 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.039s	user 0.015s	sys 0.022s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17851,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:17.385052 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=2.188937
I20260812 06:18:17.396329 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.011s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3847,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.396796 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushMRSOp(821108b946014e6e8b5033190d4d73b1): perf score=1.000000
I20260812 06:18:17.427825 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushMRSOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":264,"dirs.run_wall_time_us":1413,"drs_written":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1515,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:17.428584 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling LogGCOp(821108b946014e6e8b5033190d4d73b1): free 128867715 bytes of WAL
I20260812 06:18:17.428867 14901 log_reader.cc:385] T 821108b946014e6e8b5033190d4d73b1: removed 13 log segments from log reader
I20260812 06:18:17.428932 14901 log.cc:1079] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/821108b946014e6e8b5033190d4d73b1/wal-000000027 (ops 128-132)
I20260812 06:18:17.428987 14901 log.cc:1079] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/821108b946014e6e8b5033190d4d73b1/wal-000000028 (ops 133-136)
I20260812 06:18:17.429023 14901 log.cc:1079] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/821108b946014e6e8b5033190d4d73b1/wal-000000029 (ops 137-141)
I20260812 06:18:17.429055 14901 log.cc:1079] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/821108b946014e6e8b5033190d4d73b1/wal-000000030 (ops 142-146)
I20260812 06:18:17.429092 14901 log.cc:1079] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/821108b946014e6e8b5033190d4d73b1/wal-000000031 (ops 147-151)
I20260812 06:18:17.429133 14901 log.cc:1079] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/821108b946014e6e8b5033190d4d73b1/wal-000000032 (ops 152-156)
I20260812 06:18:17.429180 14901 log.cc:1079] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/821108b946014e6e8b5033190d4d73b1/wal-000000033 (ops 157-160)
I20260812 06:18:17.429221 14901 log.cc:1079] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/821108b946014e6e8b5033190d4d73b1/wal-000000034 (ops 161-165)
I20260812 06:18:17.429260 14901 log.cc:1079] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/821108b946014e6e8b5033190d4d73b1/wal-000000035 (ops 166-170)
I20260812 06:18:17.429301 14901 log.cc:1079] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/821108b946014e6e8b5033190d4d73b1/wal-000000036 (ops 171-174)
I20260812 06:18:17.429359 14901 log.cc:1079] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/821108b946014e6e8b5033190d4d73b1/wal-000000037 (ops 175-179)
I20260812 06:18:17.429386 14901 log.cc:1079] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/821108b946014e6e8b5033190d4d73b1/wal-000000038 (ops 180-184)
I20260812 06:18:17.429409 14901 log.cc:1079] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/821108b946014e6e8b5033190d4d73b1/wal-000000039 (ops 185-189)
I20260812 06:18:17.456416 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: LogGCOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.028s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:18:17.456939 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=4.173312
I20260812 06:18:17.472177 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":5907729,"delete_count":0,"lbm_write_time_us":6300,"lbm_writes_lt_1ms":147,"reinsert_count":0,"update_count":720}
I20260812 06:18:17.472690 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling UndoDeltaBlockGCOp(821108b946014e6e8b5033190d4d73b1): 472 bytes on disk
I20260812 06:18:17.473215 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: UndoDeltaBlockGCOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:18:17.474001 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=1.196750
I20260812 06:18:17.491681 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.017s	user 0.007s	sys 0.003s Metrics: {"bytes_written":2297554,"delete_count":0,"lbm_write_time_us":4594,"lbm_writes_lt_1ms":59,"reinsert_count":0,"update_count":280}
I20260812 06:18:17.492353 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling MajorDeltaCompactionOp(821108b946014e6e8b5033190d4d73b1): perf score=1.000000
I20260812 06:18:17.664265 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: MajorDeltaCompactionOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.172s	user 0.137s	sys 0.032s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836334,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":341,"lbm_read_time_us":12254,"lbm_reads_lt_1ms":666,"lbm_write_time_us":36853,"lbm_writes_lt_1ms":643,"mutex_wait_us":46,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":39424,"thread_start_us":92,"threads_started":1,"update_count":3000}
I20260812 06:18:17.665079 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=14.095187
I20260812 06:18:17.696977 14788 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.082s	user 1.840s	sys 0.163s
I20260812 06:18:17.712220 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.047s	user 0.033s	sys 0.013s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21909,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:17.712828 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1): perf score=2.188937
I20260812 06:18:17.722935 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: FlushDeltaMemStoresOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.010s	user 0.007s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4014,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.723428 14977 maintenance_manager.cc:419] P 65fe30f48b234e1f946d2dead2a68cc6: Scheduling MajorDeltaCompactionOp(821108b946014e6e8b5033190d4d73b1): perf score=1.000000
I20260812 06:18:17.736227 14788 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.038s	user 0.002s	sys 0.004s
I20260812 06:18:17.736933 14788 tablet_server.cc:179] TabletServer@127.14.113.1:0 shutting down...
I20260812 06:18:17.846822 14901 maintenance_manager.cc:643] P 65fe30f48b234e1f946d2dead2a68cc6: MajorDeltaCompactionOp(821108b946014e6e8b5033190d4d73b1) complete. Timing: real 0.123s	user 0.115s	sys 0.008s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4221425,"cfile_cache_miss":502,"cfile_cache_miss_bytes":20512299,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":381,"lbm_read_time_us":8712,"lbm_reads_lt_1ms":518,"lbm_write_time_us":24310,"lbm_writes_lt_1ms":543,"mutex_wait_us":90,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:17.847642 14788 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:17.848119 14788 tablet_replica.cc:333] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6: stopping tablet replica
I20260812 06:18:17.848394 14788 raft_consensus.cc:2243] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:17.848640 14788 raft_consensus.cc:2272] T 821108b946014e6e8b5033190d4d73b1 P 65fe30f48b234e1f946d2dead2a68cc6 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:17.865335 14788 tablet_server.cc:196] TabletServer@127.14.113.1:0 shutdown complete.
I20260812 06:18:17.893680 14788 master.cc:562] Master@127.14.113.62:33219 shutting down...
I20260812 06:18:17.897601 14788 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 874aed1303074cefaef40f26f97f015a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:17.897851 14788 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 874aed1303074cefaef40f26f97f015a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:17.897948 14788 tablet_replica.cc:333] T 00000000000000000000000000000000 P 874aed1303074cefaef40f26f97f015a: stopping tablet replica
I20260812 06:18:17.910557 14788 master.cc:584] Master@127.14.113.62:33219 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5647 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:18.019649 14788 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.14.113.62:34455
I20260812 06:18:18.020162 14788 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:18.022440 15013 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:18.022472 15012 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:18.022640 14788 server_base.cc:1061] running on GCE node
W20260812 06:18:18.022648 15015 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:18.022922 14788 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:18.022979 14788 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:18.022996 14788 hybrid_clock.cc:648] HybridClock initialized: now 1786515498022996 us; error 0 us; skew 500 ppm
I20260812 06:18:18.024020 14788 webserver.cc:533] Webserver started at http://127.14.113.62:35809/ using document root <none> and password file <none>
I20260812 06:18:18.024209 14788 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:18.024267 14788 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:18.024415 14788 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:18.024859 14788 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/master-0-root/instance:
uuid: "1b8297d354b74650a737d44e9cbe8714"
format_stamp: "Formatted at 2026-08-12 06:18:18 on dist-test-slave-27sr"
I20260812 06:18:18.026489 14788 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:18.027505 15020 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:18.027776 14788 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:18.027860 14788 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/master-0-root
uuid: "1b8297d354b74650a737d44e9cbe8714"
format_stamp: "Formatted at 2026-08-12 06:18:18 on dist-test-slave-27sr"
I20260812 06:18:18.027969 14788 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:18.047371 14788 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:18.047784 14788 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:18.052407 14788 rpc_server.cc:307] RPC server started. Bound to: 127.14.113.62:34455
I20260812 06:18:18.054716 15084 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.14.113.62:34455 every 8 connection(s)
I20260812 06:18:18.055209 15085 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:18.057116 15085 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1b8297d354b74650a737d44e9cbe8714: Bootstrap starting.
I20260812 06:18:18.057938 15085 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 1b8297d354b74650a737d44e9cbe8714: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:18.059156 15085 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1b8297d354b74650a737d44e9cbe8714: No bootstrap required, opened a new log
I20260812 06:18:18.059615 15085 raft_consensus.cc:359] T 00000000000000000000000000000000 P 1b8297d354b74650a737d44e9cbe8714 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1b8297d354b74650a737d44e9cbe8714" member_type: VOTER }
I20260812 06:18:18.059705 15085 raft_consensus.cc:385] T 00000000000000000000000000000000 P 1b8297d354b74650a737d44e9cbe8714 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:18.059727 15085 raft_consensus.cc:740] T 00000000000000000000000000000000 P 1b8297d354b74650a737d44e9cbe8714 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 1b8297d354b74650a737d44e9cbe8714, State: Initialized, Role: FOLLOWER
I20260812 06:18:18.060072 15085 consensus_queue.cc:260] T 00000000000000000000000000000000 P 1b8297d354b74650a737d44e9cbe8714 [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: "1b8297d354b74650a737d44e9cbe8714" member_type: VOTER }
I20260812 06:18:18.060181 15085 raft_consensus.cc:399] T 00000000000000000000000000000000 P 1b8297d354b74650a737d44e9cbe8714 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:18.060209 15085 raft_consensus.cc:493] T 00000000000000000000000000000000 P 1b8297d354b74650a737d44e9cbe8714 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:18.060346 15085 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 1b8297d354b74650a737d44e9cbe8714 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:18.061134 15085 raft_consensus.cc:515] T 00000000000000000000000000000000 P 1b8297d354b74650a737d44e9cbe8714 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1b8297d354b74650a737d44e9cbe8714" member_type: VOTER }
I20260812 06:18:18.061304 15085 leader_election.cc:304] T 00000000000000000000000000000000 P 1b8297d354b74650a737d44e9cbe8714 [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: 1b8297d354b74650a737d44e9cbe8714; no voters: 
I20260812 06:18:18.061537 15085 leader_election.cc:290] T 00000000000000000000000000000000 P 1b8297d354b74650a737d44e9cbe8714 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:18.061941 15089 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 1b8297d354b74650a737d44e9cbe8714 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:18.062198 15089 raft_consensus.cc:697] T 00000000000000000000000000000000 P 1b8297d354b74650a737d44e9cbe8714 [term 1 LEADER]: Becoming Leader. State: Replica: 1b8297d354b74650a737d44e9cbe8714, State: Running, Role: LEADER
I20260812 06:18:18.062376 15089 consensus_queue.cc:237] T 00000000000000000000000000000000 P 1b8297d354b74650a737d44e9cbe8714 [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: "1b8297d354b74650a737d44e9cbe8714" member_type: VOTER }
I20260812 06:18:18.062407 15085 sys_catalog.cc:565] T 00000000000000000000000000000000 P 1b8297d354b74650a737d44e9cbe8714 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:18.062901 15090 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1b8297d354b74650a737d44e9cbe8714 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "1b8297d354b74650a737d44e9cbe8714" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1b8297d354b74650a737d44e9cbe8714" member_type: VOTER } }
I20260812 06:18:18.062934 15091 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1b8297d354b74650a737d44e9cbe8714 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 1b8297d354b74650a737d44e9cbe8714. Latest consensus state: current_term: 1 leader_uuid: "1b8297d354b74650a737d44e9cbe8714" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1b8297d354b74650a737d44e9cbe8714" member_type: VOTER } }
I20260812 06:18:18.063061 15090 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1b8297d354b74650a737d44e9cbe8714 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:18.063133 15091 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1b8297d354b74650a737d44e9cbe8714 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:18.063989 15098 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:18.064888 15098 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:18.065076 14788 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:18.067009 15098 catalog_manager.cc:1383] Generated new cluster ID: 7609fc9993164f91b4e97ff4667f6db0
I20260812 06:18:18.067099 15098 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:18.077387 15098 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:18.078128 15098 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:18.089183 15098 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 1b8297d354b74650a737d44e9cbe8714: Generated new TSK 0
I20260812 06:18:18.089414 15098 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:18.097497 14788 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:18:18.099952 14788 server_base.cc:1061] running on GCE node
W20260812 06:18:18.099969 15114 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:18.099992 15119 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:18.100111 15112 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:18.100422 14788 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:18.100468 14788 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:18.100484 14788 hybrid_clock.cc:648] HybridClock initialized: now 1786515498100484 us; error 0 us; skew 500 ppm
I20260812 06:18:18.101405 14788 webserver.cc:533] Webserver started at http://127.14.113.1:35581/ using document root <none> and password file <none>
I20260812 06:18:18.101590 14788 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:18.101660 14788 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:18.101754 14788 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:18.102171 14788 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/instance:
uuid: "3cadbc37804c4aa1b8685b32a7f21cf1"
format_stamp: "Formatted at 2026-08-12 06:18:18 on dist-test-slave-27sr"
I20260812 06:18:18.103679 14788 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:18.104673 15124 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:18.104980 14788 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:18.105046 14788 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root
uuid: "3cadbc37804c4aa1b8685b32a7f21cf1"
format_stamp: "Formatted at 2026-08-12 06:18:18 on dist-test-slave-27sr"
I20260812 06:18:18.105145 14788 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:18.123636 14788 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:18.124161 14788 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:18.124512 14788 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:18.125027 14788 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:18.125065 14788 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:18.125128 14788 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:18.125167 14788 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:18.129679 14788 rpc_server.cc:307] RPC server started. Bound to: 127.14.113.1:36175
I20260812 06:18:18.131544 15197 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.14.113.1:36175 every 8 connection(s)
I20260812 06:18:18.142565 15198 heartbeater.cc:344] Connected to a master server at 127.14.113.62:34455
I20260812 06:18:18.142729 15198 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:18.143000 15198 heartbeater.cc:507] Master 127.14.113.62:34455 requested a full tablet report, sending...
I20260812 06:18:18.143793 15041 ts_manager.cc:194] Registered new tserver with Master: 3cadbc37804c4aa1b8685b32a7f21cf1 (127.14.113.1:36175)
I20260812 06:18:18.144569 15041 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:60140
I20260812 06:18:18.144728 14788 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.014400353s
I20260812 06:18:18.152467 15041 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:60150:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:18.161556 15158 tablet_service.cc:1511] Processing CreateTablet for tablet 1421e742548847dfb88bdaeae8815724 (DEFAULT_TABLE table=heavy-update-compaction-test [id=9c1b9fec31bd4a7b937196f556c09e9c]), partition=
I20260812 06:18:18.161914 15158 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 1421e742548847dfb88bdaeae8815724. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:18.164242 15215 tablet_bootstrap.cc:492] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Bootstrap starting.
I20260812 06:18:18.165133 15215 tablet_bootstrap.cc:654] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:18.166455 15215 tablet_bootstrap.cc:492] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: No bootstrap required, opened a new log
I20260812 06:18:18.166567 15215 ts_tablet_manager.cc:1403] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:18.167095 15215 raft_consensus.cc:359] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3cadbc37804c4aa1b8685b32a7f21cf1" member_type: VOTER last_known_addr { host: "127.14.113.1" port: 36175 } }
I20260812 06:18:18.167219 15215 raft_consensus.cc:385] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:18.167255 15215 raft_consensus.cc:740] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 3cadbc37804c4aa1b8685b32a7f21cf1, State: Initialized, Role: FOLLOWER
I20260812 06:18:18.167418 15215 consensus_queue.cc:260] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1 [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: "3cadbc37804c4aa1b8685b32a7f21cf1" member_type: VOTER last_known_addr { host: "127.14.113.1" port: 36175 } }
I20260812 06:18:18.167508 15215 raft_consensus.cc:399] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:18.167532 15215 raft_consensus.cc:493] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:18.167570 15215 raft_consensus.cc:3060] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:18.168376 15215 raft_consensus.cc:515] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3cadbc37804c4aa1b8685b32a7f21cf1" member_type: VOTER last_known_addr { host: "127.14.113.1" port: 36175 } }
I20260812 06:18:18.168494 15215 leader_election.cc:304] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1 [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: 3cadbc37804c4aa1b8685b32a7f21cf1; no voters: 
I20260812 06:18:18.168658 15215 leader_election.cc:290] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:18.168828 15217 raft_consensus.cc:2804] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:18.168946 15217 raft_consensus.cc:697] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1 [term 1 LEADER]: Becoming Leader. State: Replica: 3cadbc37804c4aa1b8685b32a7f21cf1, State: Running, Role: LEADER
I20260812 06:18:18.168998 15198 heartbeater.cc:499] Master 127.14.113.62:34455 was elected leader, sending a full tablet report...
I20260812 06:18:18.168962 15215 ts_tablet_manager.cc:1434] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:18.169104 15217 consensus_queue.cc:237] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1 [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: "3cadbc37804c4aa1b8685b32a7f21cf1" member_type: VOTER last_known_addr { host: "127.14.113.1" port: 36175 } }
I20260812 06:18:18.170495 15041 catalog_manager.cc:5719] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1 reported cstate change: term changed from 0 to 1, leader changed from <none> to 3cadbc37804c4aa1b8685b32a7f21cf1 (127.14.113.1). New cstate: current_term: 1 leader_uuid: "3cadbc37804c4aa1b8685b32a7f21cf1" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3cadbc37804c4aa1b8685b32a7f21cf1" member_type: VOTER last_known_addr { host: "127.14.113.1" port: 36175 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:18.230247 14788 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.018s	sys 0.004s
I20260812 06:18:18.382093 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushMRSOp(1421e742548847dfb88bdaeae8815724): perf score=19.054940
I20260812 06:18:18.541785 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushMRSOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.159s	user 0.110s	sys 0.047s Metrics: {"bytes_written":13168993,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":219,"dirs.run_wall_time_us":860,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39409,"lbm_writes_lt_1ms":778,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1605}
I20260812 06:18:18.542526 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling LogGCOp(1421e742548847dfb88bdaeae8815724): free 20743880 bytes of WAL
I20260812 06:18:18.542765 15133 log_reader.cc:385] T 1421e742548847dfb88bdaeae8815724: removed 2 log segments from log reader
I20260812 06:18:18.542833 15133 log.cc:1079] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/1421e742548847dfb88bdaeae8815724/wal-000000001 (ops 1-6)
I20260812 06:18:18.542881 15133 log.cc:1079] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/1421e742548847dfb88bdaeae8815724/wal-000000002 (ops 7-11)
I20260812 06:18:18.548142 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: LogGCOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.005s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:18:18.548473 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling UndoDeltaBlockGCOp(1421e742548847dfb88bdaeae8815724): 16411393 bytes on disk
I20260812 06:18:18.548847 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: UndoDeltaBlockGCOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:18:18.549391 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=3.181125
I20260812 06:18:18.560591 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.011s	user 0.009s	sys 0.002s Metrics: {"bytes_written":4307786,"delete_count":0,"lbm_write_time_us":4205,"lbm_writes_lt_1ms":108,"reinsert_count":0,"update_count":525}
I20260812 06:18:18.561009 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=1.196750
I20260812 06:18:18.570118 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3036005,"delete_count":0,"lbm_write_time_us":3332,"lbm_writes_lt_1ms":77,"reinsert_count":0,"update_count":370}
I20260812 06:18:18.570606 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling MajorDeltaCompactionOp(1421e742548847dfb88bdaeae8815724): perf score=1.000000
I20260812 06:18:18.760357 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: MajorDeltaCompactionOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.189s	user 0.146s	sys 0.043s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774784,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":539,"lbm_read_time_us":12897,"lbm_reads_lt_1ms":569,"lbm_write_time_us":33327,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"thread_start_us":380,"threads_started":5,"update_count":2500}
I20260812 06:18:18.760950 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=14.095187
I20260812 06:18:18.824771 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.064s	user 0.038s	sys 0.024s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":23877,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:18.825397 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=2.188937
I20260812 06:18:18.838073 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.012s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4682,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.838760 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling MajorDeltaCompactionOp(1421e742548847dfb88bdaeae8815724): perf score=1.000000
I20260812 06:18:19.037161 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: MajorDeltaCompactionOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.198s	user 0.121s	sys 0.077s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":191,"lbm_read_time_us":15806,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31730,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13824,"update_count":2500}
I20260812 06:18:19.037804 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=14.095187
I20260812 06:18:19.104923 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.067s	user 0.027s	sys 0.036s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24096,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:19.105526 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=2.188937
I20260812 06:18:19.116703 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.011s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4342,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.117141 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling MajorDeltaCompactionOp(1421e742548847dfb88bdaeae8815724): perf score=1.000000
I20260812 06:18:19.297446 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: MajorDeltaCompactionOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.180s	user 0.088s	sys 0.088s 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":839,"lbm_read_time_us":13987,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27950,"lbm_writes_lt_1ms":543,"mutex_wait_us":337,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2500}
I20260812 06:18:19.298071 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=11.118625
I20260812 06:18:19.335547 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.037s	user 0.017s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15775,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:19.336211 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=2.188937
I20260812 06:18:19.358281 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.022s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5865,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:19.358814 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=2.188937
I20260812 06:18:19.370028 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4115,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.370608 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling MajorDeltaCompactionOp(1421e742548847dfb88bdaeae8815724): perf score=1.000000
I20260812 06:18:19.566325 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: MajorDeltaCompactionOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.195s	user 0.144s	sys 0.039s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":772,"lbm_read_time_us":11750,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28474,"lbm_writes_lt_1ms":543,"mutex_wait_us":262,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2500}
I20260812 06:18:19.566957 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=14.095187
I20260812 06:18:19.620946 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.054s	user 0.021s	sys 0.023s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20211,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:19.621487 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=2.188937
I20260812 06:18:19.633414 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4281,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.633906 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling MajorDeltaCompactionOp(1421e742548847dfb88bdaeae8815724): perf score=1.000000
I20260812 06:18:19.794080 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: MajorDeltaCompactionOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.160s	user 0.115s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":198,"lbm_read_time_us":10719,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32927,"lbm_writes_lt_1ms":543,"mutex_wait_us":56,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13696,"update_count":2500}
I20260812 06:18:19.794857 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=11.118625
I20260812 06:18:19.830032 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.035s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":15107,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:19.830593 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=2.188937
I20260812 06:18:19.855595 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.025s	user 0.006s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6006,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:19.856139 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=2.188937
I20260812 06:18:19.866880 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4111,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.867380 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushMRSOp(1421e742548847dfb88bdaeae8815724): perf score=1.000000
I20260812 06:18:19.898841 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushMRSOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.031s	user 0.022s	sys 0.007s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":76,"dirs.run_cpu_time_us":268,"dirs.run_wall_time_us":1372,"drs_written":1,"lbm_read_time_us":94,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1804,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:19.899564 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling LogGCOp(1421e742548847dfb88bdaeae8815724): free 120553388 bytes of WAL
I20260812 06:18:19.899838 15133 log_reader.cc:385] T 1421e742548847dfb88bdaeae8815724: removed 12 log segments from log reader
I20260812 06:18:19.899950 15133 log.cc:1079] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/1421e742548847dfb88bdaeae8815724/wal-000000003 (ops 12-16)
I20260812 06:18:19.900029 15133 log.cc:1079] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/1421e742548847dfb88bdaeae8815724/wal-000000004 (ops 17-20)
I20260812 06:18:19.900071 15133 log.cc:1079] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/1421e742548847dfb88bdaeae8815724/wal-000000005 (ops 21-25)
I20260812 06:18:19.900112 15133 log.cc:1079] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/1421e742548847dfb88bdaeae8815724/wal-000000006 (ops 26-30)
I20260812 06:18:19.900154 15133 log.cc:1079] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/1421e742548847dfb88bdaeae8815724/wal-000000007 (ops 31-34)
I20260812 06:18:19.900194 15133 log.cc:1079] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/1421e742548847dfb88bdaeae8815724/wal-000000008 (ops 35-39)
I20260812 06:18:19.900242 15133 log.cc:1079] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/1421e742548847dfb88bdaeae8815724/wal-000000009 (ops 40-44)
I20260812 06:18:19.900279 15133 log.cc:1079] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/1421e742548847dfb88bdaeae8815724/wal-000000010 (ops 45-49)
I20260812 06:18:19.900323 15133 log.cc:1079] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/1421e742548847dfb88bdaeae8815724/wal-000000011 (ops 50-54)
I20260812 06:18:19.900362 15133 log.cc:1079] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/1421e742548847dfb88bdaeae8815724/wal-000000012 (ops 55-59)
I20260812 06:18:19.900401 15133 log.cc:1079] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/1421e742548847dfb88bdaeae8815724/wal-000000013 (ops 60-64)
I20260812 06:18:19.900440 15133 log.cc:1079] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/1421e742548847dfb88bdaeae8815724/wal-000000014 (ops 65-69)
I20260812 06:18:19.928053 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: LogGCOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.028s	user 0.002s	sys 0.027s Metrics: {}
I20260812 06:18:19.928526 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=3.181125
I20260812 06:18:19.958343 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.030s	user 0.020s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7173,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:19.958945 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=2.188937
I20260812 06:18:19.969512 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3945,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:19.969974 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling MajorDeltaCompactionOp(1421e742548847dfb88bdaeae8815724): perf score=1.000000
I20260812 06:18:20.204308 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: MajorDeltaCompactionOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.234s	user 0.166s	sys 0.068s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979852,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":110,"lbm_read_time_us":16360,"lbm_reads_lt_1ms":775,"lbm_write_time_us":42331,"lbm_writes_lt_1ms":743,"mutex_wait_us":21,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3328,"thread_start_us":99,"threads_started":1,"update_count":3500}
I20260812 06:18:20.205618 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling UndoDeltaBlockGCOp(1421e742548847dfb88bdaeae8815724): 471 bytes on disk
I20260812 06:18:20.207491 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: UndoDeltaBlockGCOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":103,"lbm_reads_lt_1ms":4}
I20260812 06:18:20.208294 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=14.095187
I20260812 06:18:20.252997 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.045s	user 0.023s	sys 0.020s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20076,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:20.253553 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=2.188937
I20260812 06:18:20.267354 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5569,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:20.267844 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling MajorDeltaCompactionOp(1421e742548847dfb88bdaeae8815724): perf score=1.000000
I20260812 06:18:20.455289 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: MajorDeltaCompactionOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.187s	user 0.130s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":878,"lbm_read_time_us":12942,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30919,"lbm_writes_lt_1ms":543,"mutex_wait_us":81,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:18:20.455986 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=14.095187
I20260812 06:18:20.521452 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.065s	user 0.030s	sys 0.031s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":22606,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:18:20.522111 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=2.188937
I20260812 06:18:20.533084 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4282,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:20.533572 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling MajorDeltaCompactionOp(1421e742548847dfb88bdaeae8815724): perf score=1.000000
I20260812 06:18:20.721184 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: MajorDeltaCompactionOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.187s	user 0.148s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1131,"lbm_read_time_us":13703,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31228,"lbm_writes_lt_1ms":543,"mutex_wait_us":568,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2500}
I20260812 06:18:20.721769 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=11.118625
I20260812 06:18:20.763098 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.041s	user 0.026s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17410,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:20.763818 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=2.188937
I20260812 06:18:20.794041 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.030s	user 0.009s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4427,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:20.794580 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=2.188937
I20260812 06:18:20.805613 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4426,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:20.806051 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling MajorDeltaCompactionOp(1421e742548847dfb88bdaeae8815724): perf score=1.000000
I20260812 06:18:20.990326 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: MajorDeltaCompactionOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.184s	user 0.138s	sys 0.033s 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":301,"lbm_read_time_us":13054,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30728,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":78592,"update_count":2500}
I20260812 06:18:20.991080 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=14.095187
I20260812 06:18:21.049649 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.058s	user 0.029s	sys 0.028s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":27030,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:21.050209 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=2.188937
I20260812 06:18:21.074429 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.024s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5487,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:21.075009 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling MajorDeltaCompactionOp(1421e742548847dfb88bdaeae8815724): perf score=1.000000
I20260812 06:18:21.269071 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: MajorDeltaCompactionOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.194s	user 0.138s	sys 0.056s 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":333,"lbm_read_time_us":14541,"lbm_reads_lt_1ms":568,"lbm_write_time_us":31781,"lbm_writes_lt_1ms":543,"mutex_wait_us":61,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":58752,"update_count":2500}
I20260812 06:18:21.269836 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=14.095187
I20260812 06:18:21.327543 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.058s	user 0.025s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23371,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:21.328130 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=2.188937
I20260812 06:18:21.339794 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4485,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:21.340698 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling MajorDeltaCompactionOp(1421e742548847dfb88bdaeae8815724): perf score=1.000000
I20260812 06:18:21.524458 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: MajorDeltaCompactionOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.184s	user 0.109s	sys 0.062s 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":540,"lbm_read_time_us":11138,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29224,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4608,"update_count":2500}
I20260812 06:18:21.525081 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=14.095187
I20260812 06:18:21.579463 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.054s	user 0.033s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23752,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:21.580114 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=2.188937
I20260812 06:18:21.592820 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.013s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4767,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:21.593367 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushMRSOp(1421e742548847dfb88bdaeae8815724): perf score=1.000000
I20260812 06:18:21.621652 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushMRSOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.028s	user 0.021s	sys 0.006s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":273,"dirs.run_wall_time_us":1428,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2022,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:21.622488 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling LogGCOp(1421e742548847dfb88bdaeae8815724): free 132571330 bytes of WAL
I20260812 06:18:21.622753 15133 log_reader.cc:385] T 1421e742548847dfb88bdaeae8815724: removed 13 log segments from log reader
I20260812 06:18:21.622823 15133 log.cc:1079] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/1421e742548847dfb88bdaeae8815724/wal-000000015 (ops 70-74)
I20260812 06:18:21.622871 15133 log.cc:1079] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/1421e742548847dfb88bdaeae8815724/wal-000000016 (ops 75-78)
I20260812 06:18:21.622929 15133 log.cc:1079] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/1421e742548847dfb88bdaeae8815724/wal-000000017 (ops 79-83)
I20260812 06:18:21.622974 15133 log.cc:1079] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/1421e742548847dfb88bdaeae8815724/wal-000000018 (ops 84-88)
I20260812 06:18:21.623020 15133 log.cc:1079] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/1421e742548847dfb88bdaeae8815724/wal-000000019 (ops 89-93)
I20260812 06:18:21.623080 15133 log.cc:1079] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/1421e742548847dfb88bdaeae8815724/wal-000000020 (ops 94-98)
I20260812 06:18:21.623121 15133 log.cc:1079] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/1421e742548847dfb88bdaeae8815724/wal-000000021 (ops 99-103)
I20260812 06:18:21.623157 15133 log.cc:1079] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/1421e742548847dfb88bdaeae8815724/wal-000000022 (ops 104-108)
I20260812 06:18:21.623190 15133 log.cc:1079] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/1421e742548847dfb88bdaeae8815724/wal-000000023 (ops 109-113)
I20260812 06:18:21.623225 15133 log.cc:1079] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/1421e742548847dfb88bdaeae8815724/wal-000000024 (ops 114-118)
I20260812 06:18:21.623262 15133 log.cc:1079] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/1421e742548847dfb88bdaeae8815724/wal-000000025 (ops 119-123)
I20260812 06:18:21.623299 15133 log.cc:1079] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/1421e742548847dfb88bdaeae8815724/wal-000000026 (ops 124-128)
I20260812 06:18:21.623334 15133 log.cc:1079] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/1421e742548847dfb88bdaeae8815724/wal-000000027 (ops 129-132)
I20260812 06:18:21.652438 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: LogGCOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.030s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:18:21.652946 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=5.165500
I20260812 06:18:21.674147 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.021s	user 0.006s	sys 0.013s Metrics: {"bytes_written":6851278,"delete_count":0,"lbm_write_time_us":9295,"lbm_writes_lt_1ms":170,"reinsert_count":0,"update_count":835}
I20260812 06:18:21.674764 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=1.000000
I20260812 06:18:21.680760 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.006s	user 0.005s	sys 0.000s Metrics: {"bytes_written":1353977,"delete_count":0,"lbm_write_time_us":1487,"lbm_writes_lt_1ms":36,"reinsert_count":0,"update_count":165}
I20260812 06:18:21.681313 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling UndoDeltaBlockGCOp(1421e742548847dfb88bdaeae8815724): 492 bytes on disk
I20260812 06:18:21.681980 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: UndoDeltaBlockGCOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":126,"lbm_reads_lt_1ms":4}
I20260812 06:18:21.682669 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling MajorDeltaCompactionOp(1421e742548847dfb88bdaeae8815724): perf score=1.000000
I20260812 06:18:21.943634 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: MajorDeltaCompactionOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.260s	user 0.165s	sys 0.082s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":599,"lbm_read_time_us":17399,"lbm_reads_lt_1ms":774,"lbm_write_time_us":43424,"lbm_writes_lt_1ms":743,"mutex_wait_us":28,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":140416,"thread_start_us":102,"threads_started":1,"update_count":3500}
I20260812 06:18:21.944644 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=18.063937
I20260812 06:18:22.016606 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.072s	user 0.043s	sys 0.018s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":27781,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:22.017143 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=2.188937
I20260812 06:18:22.030319 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.013s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4536,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.030833 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling MajorDeltaCompactionOp(1421e742548847dfb88bdaeae8815724): perf score=1.000000
I20260812 06:18:22.264132 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: MajorDeltaCompactionOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.233s	user 0.144s	sys 0.083s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877105,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1448,"lbm_read_time_us":14752,"lbm_reads_lt_1ms":672,"lbm_write_time_us":41482,"lbm_writes_lt_1ms":643,"mutex_wait_us":703,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14464,"update_count":3000}
I20260812 06:18:22.264964 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=18.063937
I20260812 06:18:22.332512 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.067s	user 0.033s	sys 0.029s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":28021,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:22.332995 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=2.188937
I20260812 06:18:22.345288 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4475,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.345774 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling MajorDeltaCompactionOp(1421e742548847dfb88bdaeae8815724): perf score=1.000000
I20260812 06:18:22.566968 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: MajorDeltaCompactionOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.221s	user 0.176s	sys 0.035s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":723,"lbm_read_time_us":13767,"lbm_reads_lt_1ms":672,"lbm_write_time_us":36204,"lbm_writes_lt_1ms":643,"mutex_wait_us":34,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":30976,"update_count":3000}
I20260812 06:18:22.567827 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=18.063937
I20260812 06:18:22.634245 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.066s	user 0.031s	sys 0.033s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":30151,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:18:22.634784 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=2.188937
I20260812 06:18:22.647866 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4761,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.648449 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling MajorDeltaCompactionOp(1421e742548847dfb88bdaeae8815724): perf score=1.000000
I20260812 06:18:22.864497 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: MajorDeltaCompactionOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.216s	user 0.138s	sys 0.077s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877104,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":532,"lbm_read_time_us":15830,"lbm_reads_lt_1ms":664,"lbm_write_time_us":37842,"lbm_writes_lt_1ms":643,"mutex_wait_us":24,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":19840,"update_count":3000}
I20260812 06:18:22.865190 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=14.095187
I20260812 06:18:22.914788 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.049s	user 0.025s	sys 0.019s Metrics: {"bytes_written":16532975,"delete_count":0,"lbm_write_time_us":19655,"lbm_writes_lt_1ms":406,"mutex_wait_us":1184,"reinsert_count":0,"update_count":2015}
I20260812 06:18:22.915690 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=2.188937
I20260812 06:18:22.928668 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3979584,"delete_count":0,"lbm_write_time_us":4569,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:18:22.929311 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling MajorDeltaCompactionOp(1421e742548847dfb88bdaeae8815724): perf score=1.000000
I20260812 06:18:23.108770 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: MajorDeltaCompactionOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.179s	user 0.122s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":141,"lbm_read_time_us":13471,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29390,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:18:23.110102 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=15.087375
I20260812 06:18:23.162704 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.052s	user 0.023s	sys 0.024s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":24645,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":412,"reinsert_count":0,"update_count":2050}
I20260812 06:18:23.163323 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=2.188937
I20260812 06:18:23.178929 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.015s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4065,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:23.179442 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=2.188937
I20260812 06:18:23.192929 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.013s	user 0.004s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5144,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:23.193478 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushMRSOp(1421e742548847dfb88bdaeae8815724): perf score=1.000000
I20260812 06:18:23.226794 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushMRSOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.033s	user 0.026s	sys 0.005s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":227,"dirs.run_wall_time_us":1534,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1691,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:23.227490 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling LogGCOp(1421e742548847dfb88bdaeae8815724): free 128867735 bytes of WAL
I20260812 06:18:23.227741 15133 log_reader.cc:385] T 1421e742548847dfb88bdaeae8815724: removed 13 log segments from log reader
I20260812 06:18:23.227789 15133 log.cc:1079] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/1421e742548847dfb88bdaeae8815724/wal-000000028 (ops 133-137)
I20260812 06:18:23.227819 15133 log.cc:1079] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/1421e742548847dfb88bdaeae8815724/wal-000000029 (ops 138-142)
I20260812 06:18:23.227882 15133 log.cc:1079] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/1421e742548847dfb88bdaeae8815724/wal-000000030 (ops 143-147)
I20260812 06:18:23.227950 15133 log.cc:1079] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/1421e742548847dfb88bdaeae8815724/wal-000000031 (ops 148-152)
I20260812 06:18:23.227993 15133 log.cc:1079] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/1421e742548847dfb88bdaeae8815724/wal-000000032 (ops 153-157)
I20260812 06:18:23.228034 15133 log.cc:1079] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/1421e742548847dfb88bdaeae8815724/wal-000000033 (ops 158-162)
I20260812 06:18:23.228072 15133 log.cc:1079] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/1421e742548847dfb88bdaeae8815724/wal-000000034 (ops 163-166)
I20260812 06:18:23.228113 15133 log.cc:1079] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/1421e742548847dfb88bdaeae8815724/wal-000000035 (ops 167-171)
I20260812 06:18:23.228152 15133 log.cc:1079] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/1421e742548847dfb88bdaeae8815724/wal-000000036 (ops 172-176)
I20260812 06:18:23.228190 15133 log.cc:1079] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/1421e742548847dfb88bdaeae8815724/wal-000000037 (ops 177-180)
I20260812 06:18:23.228229 15133 log.cc:1079] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/1421e742548847dfb88bdaeae8815724/wal-000000038 (ops 181-185)
I20260812 06:18:23.228267 15133 log.cc:1079] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/1421e742548847dfb88bdaeae8815724/wal-000000039 (ops 186-190)
I20260812 06:18:23.228305 15133 log.cc:1079] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: Deleting log segment in path: /tmp/dist-test-task5M0fyB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515492347344-14788-0/minicluster-data/ts-0-root/wals/1421e742548847dfb88bdaeae8815724/wal-000000040 (ops 191-194)
I20260812 06:18:23.258657 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: LogGCOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.031s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:18:23.259130 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling UndoDeltaBlockGCOp(1421e742548847dfb88bdaeae8815724): 483 bytes on disk
I20260812 06:18:23.259588 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: UndoDeltaBlockGCOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:18:23.260210 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=4.173312
I20260812 06:18:23.275404 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":5907728,"delete_count":0,"lbm_write_time_us":6033,"lbm_writes_lt_1ms":147,"reinsert_count":0,"update_count":720}
I20260812 06:18:23.275972 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724): perf score=1.196750
I20260812 06:18:23.283016 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: FlushDeltaMemStoresOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.007s	user 0.005s	sys 0.000s Metrics: {"bytes_written":2297554,"delete_count":0,"lbm_write_time_us":2214,"lbm_writes_lt_1ms":59,"reinsert_count":0,"update_count":280}
I20260812 06:18:23.283524 15199 maintenance_manager.cc:419] P 3cadbc37804c4aa1b8685b32a7f21cf1: Scheduling MajorDeltaCompactionOp(1421e742548847dfb88bdaeae8815724): perf score=1.000000
I20260812 06:18:23.313278 14788 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.083s	user 1.819s	sys 0.205s
I20260812 06:18:23.422602 14788 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.109s	user 0.001s	sys 0.000s
I20260812 06:18:23.423182 14788 tablet_server.cc:179] TabletServer@127.14.113.1:0 shutting down...
I20260812 06:18:23.499045 15133 maintenance_manager.cc:643] P 3cadbc37804c4aa1b8685b32a7f21cf1: MajorDeltaCompactionOp(1421e742548847dfb88bdaeae8815724) complete. Timing: real 0.215s	user 0.155s	sys 0.059s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37082227,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":878,"lbm_read_time_us":18056,"lbm_reads_lt_1ms":871,"lbm_write_time_us":38640,"lbm_writes_lt_1ms":843,"mutex_wait_us":66,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":55424,"thread_start_us":78,"threads_started":1,"update_count":4000}
I20260812 06:18:23.499825 14788 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:23.500319 14788 tablet_replica.cc:333] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1: stopping tablet replica
I20260812 06:18:23.500500 14788 raft_consensus.cc:2243] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:23.500721 14788 raft_consensus.cc:2272] T 1421e742548847dfb88bdaeae8815724 P 3cadbc37804c4aa1b8685b32a7f21cf1 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:23.506572 14788 tablet_server.cc:196] TabletServer@127.14.113.1:0 shutdown complete.
I20260812 06:18:23.571882 14788 master.cc:562] Master@127.14.113.62:34455 shutting down...
I20260812 06:18:23.576195 14788 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 1b8297d354b74650a737d44e9cbe8714 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:23.576455 14788 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 1b8297d354b74650a737d44e9cbe8714 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:23.576552 14788 tablet_replica.cc:333] T 00000000000000000000000000000000 P 1b8297d354b74650a737d44e9cbe8714: stopping tablet replica
I20260812 06:18:23.589591 14788 master.cc:584] Master@127.14.113.62:34455 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5673 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11322 ms total)

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