[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:17:08.808238 16906 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.16.130.190:39711
I20260812 06:17:08.809419 16906 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:17:08.810084 16906 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:08.818053 16921 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:08.818070 16920 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:08.818163 16906 server_base.cc:1061] running on GCE node
W20260812 06:17:08.818478 16923 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:08.819113 16906 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:08.819267 16906 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:08.819346 16906 hybrid_clock.cc:648] HybridClock initialized: now 1786515428819342 us; error 0 us; skew 500 ppm
I20260812 06:17:08.821527 16906 webserver.cc:533] Webserver started at http://127.16.130.190:43155/ using document root <none> and password file <none>
I20260812 06:17:08.822154 16906 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:08.822255 16906 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:08.822543 16906 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:08.824474 16906 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/master-0-root/instance:
uuid: "8fd2cb87d9d14ec39b2a58ce13bfbe07"
format_stamp: "Formatted at 2026-08-12 06:17:08 on dist-test-slave-z8x9"
I20260812 06:17:08.829347 16906 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.007s	sys 0.000s
I20260812 06:17:08.832464 16930 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:08.834388 16906 fs_manager.cc:730] Time spent opening block manager: real 0.004s	user 0.003s	sys 0.000s
I20260812 06:17:08.834625 16906 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/master-0-root
uuid: "8fd2cb87d9d14ec39b2a58ce13bfbe07"
format_stamp: "Formatted at 2026-08-12 06:17:08 on dist-test-slave-z8x9"
I20260812 06:17:08.834775 16906 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:08.851059 16906 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:08.851835 16906 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:17:08.852054 16906 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:08.861053 16906 rpc_server.cc:307] RPC server started. Bound to: 127.16.130.190:39711
I20260812 06:17:08.861066 17035 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.16.130.190:39711 every 8 connection(s)
I20260812 06:17:08.863677 17037 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:08.870205 17037 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8fd2cb87d9d14ec39b2a58ce13bfbe07: Bootstrap starting.
I20260812 06:17:08.873054 17037 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 8fd2cb87d9d14ec39b2a58ce13bfbe07: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:08.874264 17037 log.cc:826] T 00000000000000000000000000000000 P 8fd2cb87d9d14ec39b2a58ce13bfbe07: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:08.876353 17037 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8fd2cb87d9d14ec39b2a58ce13bfbe07: No bootstrap required, opened a new log
I20260812 06:17:08.879899 17037 raft_consensus.cc:359] T 00000000000000000000000000000000 P 8fd2cb87d9d14ec39b2a58ce13bfbe07 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8fd2cb87d9d14ec39b2a58ce13bfbe07" member_type: VOTER }
I20260812 06:17:08.880127 17037 raft_consensus.cc:385] T 00000000000000000000000000000000 P 8fd2cb87d9d14ec39b2a58ce13bfbe07 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:08.880177 17037 raft_consensus.cc:740] T 00000000000000000000000000000000 P 8fd2cb87d9d14ec39b2a58ce13bfbe07 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8fd2cb87d9d14ec39b2a58ce13bfbe07, State: Initialized, Role: FOLLOWER
I20260812 06:17:08.880832 17037 consensus_queue.cc:260] T 00000000000000000000000000000000 P 8fd2cb87d9d14ec39b2a58ce13bfbe07 [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: "8fd2cb87d9d14ec39b2a58ce13bfbe07" member_type: VOTER }
I20260812 06:17:08.880992 17037 raft_consensus.cc:399] T 00000000000000000000000000000000 P 8fd2cb87d9d14ec39b2a58ce13bfbe07 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:08.881042 17037 raft_consensus.cc:493] T 00000000000000000000000000000000 P 8fd2cb87d9d14ec39b2a58ce13bfbe07 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:08.881140 17037 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 8fd2cb87d9d14ec39b2a58ce13bfbe07 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:08.882211 17037 raft_consensus.cc:515] T 00000000000000000000000000000000 P 8fd2cb87d9d14ec39b2a58ce13bfbe07 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8fd2cb87d9d14ec39b2a58ce13bfbe07" member_type: VOTER }
I20260812 06:17:08.882731 17037 leader_election.cc:304] T 00000000000000000000000000000000 P 8fd2cb87d9d14ec39b2a58ce13bfbe07 [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: 8fd2cb87d9d14ec39b2a58ce13bfbe07; no voters: 
I20260812 06:17:08.883095 17037 leader_election.cc:290] T 00000000000000000000000000000000 P 8fd2cb87d9d14ec39b2a58ce13bfbe07 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:08.883277 17045 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 8fd2cb87d9d14ec39b2a58ce13bfbe07 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:08.883580 17045 raft_consensus.cc:697] T 00000000000000000000000000000000 P 8fd2cb87d9d14ec39b2a58ce13bfbe07 [term 1 LEADER]: Becoming Leader. State: Replica: 8fd2cb87d9d14ec39b2a58ce13bfbe07, State: Running, Role: LEADER
I20260812 06:17:08.884016 17045 consensus_queue.cc:237] T 00000000000000000000000000000000 P 8fd2cb87d9d14ec39b2a58ce13bfbe07 [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: "8fd2cb87d9d14ec39b2a58ce13bfbe07" member_type: VOTER }
I20260812 06:17:08.884343 17037 sys_catalog.cc:565] T 00000000000000000000000000000000 P 8fd2cb87d9d14ec39b2a58ce13bfbe07 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:08.886556 17047 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8fd2cb87d9d14ec39b2a58ce13bfbe07 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "8fd2cb87d9d14ec39b2a58ce13bfbe07" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8fd2cb87d9d14ec39b2a58ce13bfbe07" member_type: VOTER } }
I20260812 06:17:08.886629 17048 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8fd2cb87d9d14ec39b2a58ce13bfbe07 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 8fd2cb87d9d14ec39b2a58ce13bfbe07. Latest consensus state: current_term: 1 leader_uuid: "8fd2cb87d9d14ec39b2a58ce13bfbe07" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8fd2cb87d9d14ec39b2a58ce13bfbe07" member_type: VOTER } }
I20260812 06:17:08.886722 17047 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8fd2cb87d9d14ec39b2a58ce13bfbe07 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:08.886761 17048 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8fd2cb87d9d14ec39b2a58ce13bfbe07 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:08.887215 17066 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:08.887259 16906 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:08.890043 17066 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:08.896396 17066 catalog_manager.cc:1383] Generated new cluster ID: 8588bfd1e6c9477fbe0dd953aac6e06a
I20260812 06:17:08.896502 17066 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:08.921540 17066 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:08.922622 17066 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:08.928962 17066 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 8fd2cb87d9d14ec39b2a58ce13bfbe07: Generated new TSK 0
I20260812 06:17:08.929770 17066 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:08.952589 16906 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:08.955981 17077 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:08.956020 17083 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:08.956120 16906 server_base.cc:1061] running on GCE node
W20260812 06:17:08.956223 17081 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:08.956538 16906 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:08.956609 16906 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:08.956635 16906 hybrid_clock.cc:648] HybridClock initialized: now 1786515428956635 us; error 0 us; skew 500 ppm
I20260812 06:17:08.957854 16906 webserver.cc:533] Webserver started at http://127.16.130.129:33601/ using document root <none> and password file <none>
I20260812 06:17:08.958046 16906 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:08.958134 16906 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:08.958225 16906 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:08.958643 16906 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root/instance:
uuid: "ecd6147757ca4d77821a12192efb7728"
format_stamp: "Formatted at 2026-08-12 06:17:08 on dist-test-slave-z8x9"
I20260812 06:17:08.960294 16906 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:08.961421 17096 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:08.961689 16906 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:08.961771 16906 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root
uuid: "ecd6147757ca4d77821a12192efb7728"
format_stamp: "Formatted at 2026-08-12 06:17:08 on dist-test-slave-z8x9"
I20260812 06:17:08.961874 16906 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:08.968935 16906 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:08.969492 16906 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:08.970047 16906 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:08.970952 16906 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:08.971009 16906 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:08.971086 16906 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:08.971127 16906 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:08.978806 16906 rpc_server.cc:307] RPC server started. Bound to: 127.16.130.129:34471
I20260812 06:17:08.978821 17229 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.16.130.129:34471 every 8 connection(s)
I20260812 06:17:08.990463 17230 heartbeater.cc:344] Connected to a master server at 127.16.130.190:39711
I20260812 06:17:08.990818 17230 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:08.991367 17230 heartbeater.cc:507] Master 127.16.130.190:39711 requested a full tablet report, sending...
I20260812 06:17:08.993777 16959 ts_manager.cc:194] Registered new tserver with Master: ecd6147757ca4d77821a12192efb7728 (127.16.130.129:34471)
I20260812 06:17:08.994305 16906 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.014760072s
I20260812 06:17:08.995374 16959 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:46208
I20260812 06:17:09.005033 16959 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:46212:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:09.021898 17156 tablet_service.cc:1511] Processing CreateTablet for tablet 49e0e211957a4c76ab58079151d8108e (DEFAULT_TABLE table=heavy-update-compaction-test [id=a8e25fa9c7184b96a19cbf06567d87ed]), partition=
I20260812 06:17:09.022411 17156 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 49e0e211957a4c76ab58079151d8108e. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:09.026060 17248 tablet_bootstrap.cc:492] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Bootstrap starting.
I20260812 06:17:09.027453 17248 tablet_bootstrap.cc:654] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:09.029345 17248 tablet_bootstrap.cc:492] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: No bootstrap required, opened a new log
I20260812 06:17:09.029546 17248 ts_tablet_manager.cc:1403] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Time spent bootstrapping tablet: real 0.004s	user 0.003s	sys 0.000s
I20260812 06:17:09.030222 17248 raft_consensus.cc:359] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ecd6147757ca4d77821a12192efb7728" member_type: VOTER last_known_addr { host: "127.16.130.129" port: 34471 } }
I20260812 06:17:09.030380 17248 raft_consensus.cc:385] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:09.030419 17248 raft_consensus.cc:740] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ecd6147757ca4d77821a12192efb7728, State: Initialized, Role: FOLLOWER
I20260812 06:17:09.030627 17248 consensus_queue.cc:260] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728 [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: "ecd6147757ca4d77821a12192efb7728" member_type: VOTER last_known_addr { host: "127.16.130.129" port: 34471 } }
I20260812 06:17:09.030748 17248 raft_consensus.cc:399] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:09.030789 17248 raft_consensus.cc:493] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:09.030838 17248 raft_consensus.cc:3060] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:09.031976 17248 raft_consensus.cc:515] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ecd6147757ca4d77821a12192efb7728" member_type: VOTER last_known_addr { host: "127.16.130.129" port: 34471 } }
I20260812 06:17:09.032166 17248 leader_election.cc:304] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728 [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: ecd6147757ca4d77821a12192efb7728; no voters: 
I20260812 06:17:09.032430 17248 leader_election.cc:290] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:09.032881 17248 ts_tablet_manager.cc:1434] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:09.032956 17255 raft_consensus.cc:2804] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:09.033378 17255 raft_consensus.cc:697] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728 [term 1 LEADER]: Becoming Leader. State: Replica: ecd6147757ca4d77821a12192efb7728, State: Running, Role: LEADER
I20260812 06:17:09.033466 17230 heartbeater.cc:499] Master 127.16.130.190:39711 was elected leader, sending a full tablet report...
I20260812 06:17:09.033638 17255 consensus_queue.cc:237] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728 [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: "ecd6147757ca4d77821a12192efb7728" member_type: VOTER last_known_addr { host: "127.16.130.129" port: 34471 } }
I20260812 06:17:09.037583 16959 catalog_manager.cc:5719] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728 reported cstate change: term changed from 0 to 1, leader changed from <none> to ecd6147757ca4d77821a12192efb7728 (127.16.130.129). New cstate: current_term: 1 leader_uuid: "ecd6147757ca4d77821a12192efb7728" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ecd6147757ca4d77821a12192efb7728" member_type: VOTER last_known_addr { host: "127.16.130.129" port: 34471 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:09.114543 16906 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.070s	user 0.023s	sys 0.004s
I20260812 06:17:09.230120 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushMRSOp(49e0e211957a4c76ab58079151d8108e): perf score=15.086190
I20260812 06:17:09.404390 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushMRSOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.174s	user 0.131s	sys 0.032s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":301,"delete_count":0,"dirs.queue_time_us":94,"dirs.run_cpu_time_us":235,"dirs.run_wall_time_us":1100,"drs_written":1,"lbm_read_time_us":87,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41866,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":33152,"thread_start_us":196,"threads_started":1,"update_count":1500}
I20260812 06:17:09.405704 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling LogGCOp(49e0e211957a4c76ab58079151d8108e): free 8725963 bytes of WAL
I20260812 06:17:09.406067 17107 log_reader.cc:385] T 49e0e211957a4c76ab58079151d8108e: removed 1 log segments from log reader
I20260812 06:17:09.406139 17107 log.cc:1079] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/49e0e211957a4c76ab58079151d8108e/wal-000000001 (ops 1-6)
I20260812 06:17:09.408617 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: LogGCOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:09.408993 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling UndoDeltaBlockGCOp(49e0e211957a4c76ab58079151d8108e): 12308958 bytes on disk
I20260812 06:17:09.410120 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: UndoDeltaBlockGCOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":101,"lbm_reads_lt_1ms":4}
I20260812 06:17:09.410594 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=2.188937
I20260812 06:17:09.434345 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.023s	user 0.019s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7710,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:09.435230 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling MajorDeltaCompactionOp(49e0e211957a4c76ab58079151d8108e): perf score=1.000000
I20260812 06:17:09.575492 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: MajorDeltaCompactionOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.140s	user 0.112s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1683,"lbm_read_time_us":8485,"lbm_reads_lt_1ms":460,"lbm_write_time_us":26007,"lbm_writes_lt_1ms":443,"mutex_wait_us":321,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":21504,"thread_start_us":334,"threads_started":5,"update_count":2000}
I20260812 06:17:09.576205 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=10.126437
I20260812 06:17:09.619750 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.043s	user 0.029s	sys 0.012s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":18320,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:09.620436 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=2.188937
I20260812 06:17:09.633345 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4492,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:09.633872 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling MajorDeltaCompactionOp(49e0e211957a4c76ab58079151d8108e): perf score=1.000000
I20260812 06:17:09.772698 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: MajorDeltaCompactionOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.139s	user 0.109s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1284,"lbm_read_time_us":9887,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27429,"lbm_writes_lt_1ms":443,"mutex_wait_us":368,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2000}
I20260812 06:17:09.773557 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=10.126437
I20260812 06:17:09.817544 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.044s	user 0.029s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20846,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:17:09.818055 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=2.188937
I20260812 06:17:09.830044 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4507,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:09.830603 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling MajorDeltaCompactionOp(49e0e211957a4c76ab58079151d8108e): perf score=1.000000
I20260812 06:17:09.963742 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: MajorDeltaCompactionOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.133s	user 0.103s	sys 0.030s 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":1355,"lbm_read_time_us":9518,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26113,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:17:09.964548 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=10.126437
I20260812 06:17:10.034922 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.070s	user 0.033s	sys 0.035s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":25211,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:10.035602 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=2.188937
I20260812 06:17:10.051296 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5207,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.052095 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling MajorDeltaCompactionOp(49e0e211957a4c76ab58079151d8108e): perf score=1.000000
I20260812 06:17:10.236580 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: MajorDeltaCompactionOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.184s	user 0.120s	sys 0.064s 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":399,"lbm_read_time_us":13270,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27825,"lbm_writes_lt_1ms":443,"mutex_wait_us":60,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":45056,"update_count":2000}
I20260812 06:17:10.237315 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=10.126437
I20260812 06:17:10.284703 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.047s	user 0.038s	sys 0.005s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19300,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:10.285494 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=2.188937
I20260812 06:17:10.297320 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4310,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.298026 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling MajorDeltaCompactionOp(49e0e211957a4c76ab58079151d8108e): perf score=1.000000
I20260812 06:17:10.444104 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: MajorDeltaCompactionOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.146s	user 0.126s	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":172,"lbm_read_time_us":9591,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29628,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":2000}
I20260812 06:17:10.444818 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=10.126437
I20260812 06:17:10.494480 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.049s	user 0.037s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":22919,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:10.495101 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=2.188937
I20260812 06:17:10.512826 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.017s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5627,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.513588 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling MajorDeltaCompactionOp(49e0e211957a4c76ab58079151d8108e): perf score=1.000000
I20260812 06:17:10.647017 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: MajorDeltaCompactionOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.133s	user 0.104s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":331,"lbm_read_time_us":10813,"lbm_reads_lt_1ms":468,"lbm_write_time_us":25364,"lbm_writes_lt_1ms":443,"mutex_wait_us":56,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:17:10.647799 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=10.126437
I20260812 06:17:10.693053 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.045s	user 0.023s	sys 0.015s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17653,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:10.693751 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=2.188937
I20260812 06:17:10.705386 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.011s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4567,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.705937 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushMRSOp(49e0e211957a4c76ab58079151d8108e): perf score=1.000000
I20260812 06:17:10.736654 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushMRSOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1152509,"cfile_init":1,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":263,"dirs.run_wall_time_us":1640,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1831,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:10.737618 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling LogGCOp(49e0e211957a4c76ab58079151d8108e): free 124257231 bytes of WAL
I20260812 06:17:10.737870 17107 log_reader.cc:385] T 49e0e211957a4c76ab58079151d8108e: removed 12 log segments from log reader
I20260812 06:17:10.737915 17107 log.cc:1079] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/49e0e211957a4c76ab58079151d8108e/wal-000000002 (ops 7-11)
I20260812 06:17:10.737944 17107 log.cc:1079] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/49e0e211957a4c76ab58079151d8108e/wal-000000003 (ops 12-16)
I20260812 06:17:10.738011 17107 log.cc:1079] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/49e0e211957a4c76ab58079151d8108e/wal-000000004 (ops 17-21)
I20260812 06:17:10.738058 17107 log.cc:1079] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/49e0e211957a4c76ab58079151d8108e/wal-000000005 (ops 22-26)
I20260812 06:17:10.738099 17107 log.cc:1079] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/49e0e211957a4c76ab58079151d8108e/wal-000000006 (ops 27-31)
I20260812 06:17:10.738147 17107 log.cc:1079] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/49e0e211957a4c76ab58079151d8108e/wal-000000007 (ops 32-36)
I20260812 06:17:10.738186 17107 log.cc:1079] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/49e0e211957a4c76ab58079151d8108e/wal-000000008 (ops 37-41)
I20260812 06:17:10.738224 17107 log.cc:1079] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/49e0e211957a4c76ab58079151d8108e/wal-000000009 (ops 42-46)
I20260812 06:17:10.738260 17107 log.cc:1079] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/49e0e211957a4c76ab58079151d8108e/wal-000000010 (ops 47-51)
I20260812 06:17:10.738297 17107 log.cc:1079] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/49e0e211957a4c76ab58079151d8108e/wal-000000011 (ops 52-56)
I20260812 06:17:10.738337 17107 log.cc:1079] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/49e0e211957a4c76ab58079151d8108e/wal-000000012 (ops 57-60)
I20260812 06:17:10.738376 17107 log.cc:1079] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/49e0e211957a4c76ab58079151d8108e/wal-000000013 (ops 61-65)
I20260812 06:17:10.767609 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: LogGCOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.030s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:17:10.768194 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling UndoDeltaBlockGCOp(49e0e211957a4c76ab58079151d8108e): 448 bytes on disk
I20260812 06:17:10.768760 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: UndoDeltaBlockGCOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4}
I20260812 06:17:10.769361 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=3.181125
I20260812 06:17:10.787106 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.018s	user 0.015s	sys 0.001s Metrics: {"bytes_written":4553933,"delete_count":0,"lbm_write_time_us":7045,"lbm_writes_lt_1ms":114,"reinsert_count":0,"update_count":555}
I20260812 06:17:10.787640 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=2.188937
I20260812 06:17:10.797330 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3651380,"delete_count":0,"lbm_write_time_us":3444,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":445}
I20260812 06:17:10.797972 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling MajorDeltaCompactionOp(49e0e211957a4c76ab58079151d8108e): perf score=1.000000
I20260812 06:17:10.991636 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: MajorDeltaCompactionOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.193s	user 0.136s	sys 0.048s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836371,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1805,"lbm_read_time_us":11661,"lbm_reads_lt_1ms":674,"lbm_write_time_us":39678,"lbm_writes_lt_1ms":643,"mutex_wait_us":544,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4096,"thread_start_us":92,"threads_started":1,"update_count":3000}
I20260812 06:17:10.992619 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=14.095187
I20260812 06:17:11.049904 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.057s	user 0.028s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24923,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:11.050518 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=2.188937
I20260812 06:17:11.063055 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.012s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4512,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.063701 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling MajorDeltaCompactionOp(49e0e211957a4c76ab58079151d8108e): perf score=1.000000
I20260812 06:17:11.250346 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: MajorDeltaCompactionOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.186s	user 0.148s	sys 0.023s 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":447,"lbm_read_time_us":10952,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35770,"lbm_writes_lt_1ms":543,"mutex_wait_us":100,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:17:11.251081 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=14.095187
I20260812 06:17:11.306336 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.055s	user 0.038s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24617,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:11.306939 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=2.188937
I20260812 06:17:11.319113 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4084,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.319893 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling MajorDeltaCompactionOp(49e0e211957a4c76ab58079151d8108e): perf score=1.000000
I20260812 06:17:11.505493 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: MajorDeltaCompactionOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.185s	user 0.129s	sys 0.056s 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":1149,"lbm_read_time_us":12472,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31211,"lbm_writes_lt_1ms":543,"mutex_wait_us":326,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2500}
I20260812 06:17:11.506108 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=14.095187
I20260812 06:17:11.559897 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.054s	user 0.016s	sys 0.033s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":22840,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:11.560547 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling MajorDeltaCompactionOp(49e0e211957a4c76ab58079151d8108e): perf score=1.000000
I20260812 06:17:11.718214 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: MajorDeltaCompactionOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.157s	user 0.111s	sys 0.040s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631191,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":269,"lbm_read_time_us":9736,"lbm_reads_lt_1ms":463,"lbm_write_time_us":27370,"lbm_writes_lt_1ms":443,"mutex_wait_us":69,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2000}
I20260812 06:17:11.719136 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=14.095187
I20260812 06:17:11.768784 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.049s	user 0.028s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21948,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:11.769426 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=2.188937
I20260812 06:17:11.781653 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4134,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.782270 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling MajorDeltaCompactionOp(49e0e211957a4c76ab58079151d8108e): perf score=1.000000
I20260812 06:17:11.972057 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: MajorDeltaCompactionOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.189s	user 0.113s	sys 0.069s 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":1649,"lbm_read_time_us":14150,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32898,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2500}
I20260812 06:17:11.972811 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=11.118625
I20260812 06:17:12.014165 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.041s	user 0.037s	sys 0.003s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18111,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:12.015080 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=2.188937
I20260812 06:17:12.032421 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.017s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5866,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:12.032960 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling MajorDeltaCompactionOp(49e0e211957a4c76ab58079151d8108e): perf score=1.000000
I20260812 06:17:12.165692 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: MajorDeltaCompactionOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.133s	user 0.105s	sys 0.027s 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":265,"lbm_read_time_us":8917,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24983,"lbm_writes_lt_1ms":443,"mutex_wait_us":70,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:12.166654 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=11.118625
I20260812 06:17:12.242450 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.076s	user 0.038s	sys 0.004s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":40720,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:12.243145 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=6.157687
I20260812 06:17:12.272809 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.029s	user 0.014s	sys 0.008s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":9149,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:17:12.273484 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushMRSOp(49e0e211957a4c76ab58079151d8108e): perf score=1.000000
I20260812 06:17:12.311769 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushMRSOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.038s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":105,"dirs.run_cpu_time_us":286,"dirs.run_wall_time_us":1477,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1647,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:12.312510 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=3.181125
I20260812 06:17:12.328835 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.016s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4678,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:12.329507 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling LogGCOp(49e0e211957a4c76ab58079151d8108e): free 121006441 bytes of WAL
I20260812 06:17:12.329772 17107 log_reader.cc:385] T 49e0e211957a4c76ab58079151d8108e: removed 12 log segments from log reader
I20260812 06:17:12.329820 17107 log.cc:1079] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/49e0e211957a4c76ab58079151d8108e/wal-000000014 (ops 66-70)
I20260812 06:17:12.329854 17107 log.cc:1079] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/49e0e211957a4c76ab58079151d8108e/wal-000000015 (ops 71-75)
I20260812 06:17:12.329902 17107 log.cc:1079] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/49e0e211957a4c76ab58079151d8108e/wal-000000016 (ops 76-80)
I20260812 06:17:12.329952 17107 log.cc:1079] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/49e0e211957a4c76ab58079151d8108e/wal-000000017 (ops 81-85)
I20260812 06:17:12.329983 17107 log.cc:1079] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/49e0e211957a4c76ab58079151d8108e/wal-000000018 (ops 86-90)
I20260812 06:17:12.330050 17107 log.cc:1079] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/49e0e211957a4c76ab58079151d8108e/wal-000000019 (ops 91-95)
I20260812 06:17:12.330111 17107 log.cc:1079] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/49e0e211957a4c76ab58079151d8108e/wal-000000020 (ops 96-100)
I20260812 06:17:12.330157 17107 log.cc:1079] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/49e0e211957a4c76ab58079151d8108e/wal-000000021 (ops 101-104)
I20260812 06:17:12.330197 17107 log.cc:1079] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/49e0e211957a4c76ab58079151d8108e/wal-000000022 (ops 105-109)
I20260812 06:17:12.330262 17107 log.cc:1079] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/49e0e211957a4c76ab58079151d8108e/wal-000000023 (ops 110-114)
I20260812 06:17:12.330304 17107 log.cc:1079] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/49e0e211957a4c76ab58079151d8108e/wal-000000024 (ops 115-119)
I20260812 06:17:12.330335 17107 log.cc:1079] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/49e0e211957a4c76ab58079151d8108e/wal-000000025 (ops 120-124)
I20260812 06:17:12.362421 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: LogGCOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.033s	user 0.000s	sys 0.032s Metrics: {}
I20260812 06:17:12.363142 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling UndoDeltaBlockGCOp(49e0e211957a4c76ab58079151d8108e): 482 bytes on disk
I20260812 06:17:12.363711 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: UndoDeltaBlockGCOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4}
I20260812 06:17:12.364305 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=2.188937
I20260812 06:17:12.381157 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.017s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6801,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.381703 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=2.188937
I20260812 06:17:12.392328 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3844,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:12.392879 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling MajorDeltaCompactionOp(49e0e211957a4c76ab58079151d8108e): perf score=1.000000
I20260812 06:17:12.688951 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: MajorDeltaCompactionOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.296s	user 0.184s	sys 0.104s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37041310,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":642,"lbm_read_time_us":17676,"lbm_reads_lt_1ms":875,"lbm_write_time_us":50002,"lbm_writes_lt_1ms":843,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":1408,"thread_start_us":397,"threads_started":6,"update_count":4000}
I20260812 06:17:12.689692 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=18.063937
I20260812 06:17:12.769556 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.080s	user 0.055s	sys 0.016s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":32123,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:12.770148 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=2.188937
I20260812 06:17:12.786525 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.016s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5798,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.787254 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling MajorDeltaCompactionOp(49e0e211957a4c76ab58079151d8108e): perf score=1.000000
I20260812 06:17:12.993399 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: MajorDeltaCompactionOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.206s	user 0.143s	sys 0.063s 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":546,"lbm_read_time_us":14150,"lbm_reads_lt_1ms":672,"lbm_write_time_us":37003,"lbm_writes_lt_1ms":643,"mutex_wait_us":32,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":3000}
I20260812 06:17:12.994050 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=14.095187
I20260812 06:17:13.067086 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.073s	user 0.040s	sys 0.017s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":25652,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:13.067700 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=2.188937
I20260812 06:17:13.083734 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5772,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.085300 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling MajorDeltaCompactionOp(49e0e211957a4c76ab58079151d8108e): perf score=1.000000
I20260812 06:17:13.274351 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: MajorDeltaCompactionOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.189s	user 0.141s	sys 0.045s 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":907,"lbm_read_time_us":14259,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34919,"lbm_writes_lt_1ms":543,"mutex_wait_us":100,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2500}
I20260812 06:17:13.275045 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=11.118625
I20260812 06:17:13.341912 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.067s	user 0.034s	sys 0.027s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":25261,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":310,"reinsert_count":0,"update_count":1550}
I20260812 06:17:13.342880 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=3.181125
I20260812 06:17:13.358671 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4800070,"delete_count":0,"lbm_write_time_us":6128,"lbm_writes_lt_1ms":120,"reinsert_count":0,"update_count":585}
I20260812 06:17:13.359232 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=1.196750
I20260812 06:17:13.372275 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.013s	user 0.003s	sys 0.007s Metrics: {"bytes_written":2994980,"delete_count":0,"lbm_write_time_us":4707,"lbm_writes_lt_1ms":76,"reinsert_count":0,"update_count":365}
I20260812 06:17:13.372968 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling MajorDeltaCompactionOp(49e0e211957a4c76ab58079151d8108e): perf score=1.000000
I20260812 06:17:13.558014 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: MajorDeltaCompactionOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.185s	user 0.107s	sys 0.077s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733820,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":367,"lbm_read_time_us":13741,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30354,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2500}
I20260812 06:17:13.558604 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=14.095187
I20260812 06:17:13.630862 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.072s	user 0.038s	sys 0.031s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":27445,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:13.631453 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=2.188937
I20260812 06:17:13.644616 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4763,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.645521 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling MajorDeltaCompactionOp(49e0e211957a4c76ab58079151d8108e): perf score=1.000000
I20260812 06:17:13.848536 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: MajorDeltaCompactionOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.203s	user 0.130s	sys 0.061s 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":328,"lbm_read_time_us":14948,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31055,"lbm_writes_lt_1ms":543,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":34176,"update_count":2500}
I20260812 06:17:13.849282 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=14.095187
I20260812 06:17:13.935282 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.086s	user 0.038s	sys 0.039s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":32420,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:13.936143 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=2.188937
I20260812 06:17:13.952984 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.017s	user 0.007s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6406,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.953739 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushMRSOp(49e0e211957a4c76ab58079151d8108e): perf score=1.000000
I20260812 06:17:14.015669 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushMRSOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.062s	user 0.037s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":262,"dirs.run_wall_time_us":1705,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1596,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28,"spinlock_wait_cycles":1920}
I20260812 06:17:14.016585 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling LogGCOp(49e0e211957a4c76ab58079151d8108e): free 123804437 bytes of WAL
I20260812 06:17:14.016857 17107 log_reader.cc:385] T 49e0e211957a4c76ab58079151d8108e: removed 12 log segments from log reader
I20260812 06:17:14.016912 17107 log.cc:1079] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/49e0e211957a4c76ab58079151d8108e/wal-000000026 (ops 125-129)
I20260812 06:17:14.016953 17107 log.cc:1079] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/49e0e211957a4c76ab58079151d8108e/wal-000000027 (ops 130-134)
I20260812 06:17:14.017045 17107 log.cc:1079] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/49e0e211957a4c76ab58079151d8108e/wal-000000028 (ops 135-139)
I20260812 06:17:14.017086 17107 log.cc:1079] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/49e0e211957a4c76ab58079151d8108e/wal-000000029 (ops 140-144)
I20260812 06:17:14.017150 17107 log.cc:1079] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/49e0e211957a4c76ab58079151d8108e/wal-000000030 (ops 145-149)
I20260812 06:17:14.017216 17107 log.cc:1079] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/49e0e211957a4c76ab58079151d8108e/wal-000000031 (ops 150-154)
I20260812 06:17:14.017287 17107 log.cc:1079] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/49e0e211957a4c76ab58079151d8108e/wal-000000032 (ops 155-158)
I20260812 06:17:14.017328 17107 log.cc:1079] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/49e0e211957a4c76ab58079151d8108e/wal-000000033 (ops 159-163)
I20260812 06:17:14.017351 17107 log.cc:1079] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/49e0e211957a4c76ab58079151d8108e/wal-000000034 (ops 164-168)
I20260812 06:17:14.017414 17107 log.cc:1079] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/49e0e211957a4c76ab58079151d8108e/wal-000000035 (ops 169-173)
I20260812 06:17:14.017472 17107 log.cc:1079] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/49e0e211957a4c76ab58079151d8108e/wal-000000036 (ops 174-178)
I20260812 06:17:14.017516 17107 log.cc:1079] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/49e0e211957a4c76ab58079151d8108e/wal-000000037 (ops 179-182)
I20260812 06:17:14.052778 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: LogGCOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.036s	user 0.002s	sys 0.031s Metrics: {}
I20260812 06:17:14.053315 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=3.181125
I20260812 06:17:14.083940 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.029s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7789,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:14.084581 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=2.188937
I20260812 06:17:14.098603 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.013s	user 0.011s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4534,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:14.099361 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling UndoDeltaBlockGCOp(49e0e211957a4c76ab58079151d8108e): 448 bytes on disk
I20260812 06:17:14.099972 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: UndoDeltaBlockGCOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":113,"lbm_reads_lt_1ms":4}
I20260812 06:17:14.100790 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling MajorDeltaCompactionOp(49e0e211957a4c76ab58079151d8108e): perf score=1.000000
I20260812 06:17:14.360642 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: MajorDeltaCompactionOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.260s	user 0.153s	sys 0.094s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938773,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":607,"lbm_read_time_us":20348,"lbm_reads_lt_1ms":774,"lbm_write_time_us":45781,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":382,"threads_started":6,"update_count":3500}
I20260812 06:17:14.361526 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=18.063937
I20260812 06:17:14.429979 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.068s	user 0.046s	sys 0.016s Metrics: {"bytes_written":20512321,"delete_count":0,"lbm_write_time_us":28854,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:14.430608 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e): perf score=2.188937
I20260812 06:17:14.445219 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: FlushDeltaMemStoresOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.014s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5966,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.445750 17231 maintenance_manager.cc:419] P ecd6147757ca4d77821a12192efb7728: Scheduling MajorDeltaCompactionOp(49e0e211957a4c76ab58079151d8108e): perf score=1.000000
I20260812 06:17:14.526170 16906 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.412s	user 2.003s	sys 0.165s
I20260812 06:17:14.598580 16906 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.072s	user 0.003s	sys 0.000s
I20260812 06:17:14.599284 16906 tablet_server.cc:179] TabletServer@127.16.130.129:0 shutting down...
I20260812 06:17:14.663118 17107 maintenance_manager.cc:643] P ecd6147757ca4d77821a12192efb7728: MajorDeltaCompactionOp(49e0e211957a4c76ab58079151d8108e) complete. Timing: real 0.217s	user 0.159s	sys 0.057s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836143,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1354,"lbm_read_time_us":14752,"lbm_reads_lt_1ms":668,"lbm_write_time_us":39760,"lbm_writes_lt_1ms":643,"mutex_wait_us":629,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":28928,"update_count":3000}
I20260812 06:17:14.665095 16906 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:14.666198 16906 tablet_replica.cc:333] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728: stopping tablet replica
I20260812 06:17:14.666584 16906 raft_consensus.cc:2243] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:14.668275 16906 raft_consensus.cc:2272] T 49e0e211957a4c76ab58079151d8108e P ecd6147757ca4d77821a12192efb7728 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:14.687863 16906 tablet_server.cc:196] TabletServer@127.16.130.129:0 shutdown complete.
I20260812 06:17:14.717031 16906 master.cc:562] Master@127.16.130.190:39711 shutting down...
I20260812 06:17:14.722651 16906 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 8fd2cb87d9d14ec39b2a58ce13bfbe07 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:14.722915 16906 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 8fd2cb87d9d14ec39b2a58ce13bfbe07 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:14.723011 16906 tablet_replica.cc:333] T 00000000000000000000000000000000 P 8fd2cb87d9d14ec39b2a58ce13bfbe07: stopping tablet replica
I20260812 06:17:14.736516 16906 master.cc:584] Master@127.16.130.190:39711 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (6028 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:14.836534 16906 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.16.130.190:37697
I20260812 06:17:14.836967 16906 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:14.839864 17309 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:14.839900 16906 server_base.cc:1061] running on GCE node
W20260812 06:17:14.839864 17307 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:14.840047 17313 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:14.840279 16906 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:14.840359 16906 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:14.840387 16906 hybrid_clock.cc:648] HybridClock initialized: now 1786515434840386 us; error 0 us; skew 500 ppm
I20260812 06:17:14.841409 16906 webserver.cc:533] Webserver started at http://127.16.130.190:45007/ using document root <none> and password file <none>
I20260812 06:17:14.841598 16906 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:14.841670 16906 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:14.841750 16906 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:14.842280 16906 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/master-0-root/instance:
uuid: "6dca59d794084ef59f5a510c4be07fb4"
format_stamp: "Formatted at 2026-08-12 06:17:14 on dist-test-slave-z8x9"
I20260812 06:17:14.844058 16906 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:14.845218 17323 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:14.845551 16906 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:14.845666 16906 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/master-0-root
uuid: "6dca59d794084ef59f5a510c4be07fb4"
format_stamp: "Formatted at 2026-08-12 06:17:14 on dist-test-slave-z8x9"
I20260812 06:17:14.845770 16906 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:14.865265 16906 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:14.865702 16906 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:14.871261 16906 rpc_server.cc:307] RPC server started. Bound to: 127.16.130.190:37697
I20260812 06:17:14.872357 17426 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.16.130.190:37697 every 8 connection(s)
I20260812 06:17:14.873594 17427 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:14.883080 17427 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6dca59d794084ef59f5a510c4be07fb4: Bootstrap starting.
I20260812 06:17:14.884168 17427 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 6dca59d794084ef59f5a510c4be07fb4: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:14.885541 17427 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6dca59d794084ef59f5a510c4be07fb4: No bootstrap required, opened a new log
I20260812 06:17:14.886053 17427 raft_consensus.cc:359] T 00000000000000000000000000000000 P 6dca59d794084ef59f5a510c4be07fb4 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6dca59d794084ef59f5a510c4be07fb4" member_type: VOTER }
I20260812 06:17:14.886178 17427 raft_consensus.cc:385] T 00000000000000000000000000000000 P 6dca59d794084ef59f5a510c4be07fb4 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:14.886216 17427 raft_consensus.cc:740] T 00000000000000000000000000000000 P 6dca59d794084ef59f5a510c4be07fb4 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6dca59d794084ef59f5a510c4be07fb4, State: Initialized, Role: FOLLOWER
I20260812 06:17:14.886361 17427 consensus_queue.cc:260] T 00000000000000000000000000000000 P 6dca59d794084ef59f5a510c4be07fb4 [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: "6dca59d794084ef59f5a510c4be07fb4" member_type: VOTER }
I20260812 06:17:14.886462 17427 raft_consensus.cc:399] T 00000000000000000000000000000000 P 6dca59d794084ef59f5a510c4be07fb4 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:14.886499 17427 raft_consensus.cc:493] T 00000000000000000000000000000000 P 6dca59d794084ef59f5a510c4be07fb4 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:14.886544 17427 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 6dca59d794084ef59f5a510c4be07fb4 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:14.887579 17427 raft_consensus.cc:515] T 00000000000000000000000000000000 P 6dca59d794084ef59f5a510c4be07fb4 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6dca59d794084ef59f5a510c4be07fb4" member_type: VOTER }
I20260812 06:17:14.887735 17427 leader_election.cc:304] T 00000000000000000000000000000000 P 6dca59d794084ef59f5a510c4be07fb4 [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: 6dca59d794084ef59f5a510c4be07fb4; no voters: 
I20260812 06:17:14.887959 17427 leader_election.cc:290] T 00000000000000000000000000000000 P 6dca59d794084ef59f5a510c4be07fb4 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:14.888171 17434 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 6dca59d794084ef59f5a510c4be07fb4 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:14.888448 17434 raft_consensus.cc:697] T 00000000000000000000000000000000 P 6dca59d794084ef59f5a510c4be07fb4 [term 1 LEADER]: Becoming Leader. State: Replica: 6dca59d794084ef59f5a510c4be07fb4, State: Running, Role: LEADER
I20260812 06:17:14.888463 17427 sys_catalog.cc:565] T 00000000000000000000000000000000 P 6dca59d794084ef59f5a510c4be07fb4 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:14.888665 17434 consensus_queue.cc:237] T 00000000000000000000000000000000 P 6dca59d794084ef59f5a510c4be07fb4 [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: "6dca59d794084ef59f5a510c4be07fb4" member_type: VOTER }
I20260812 06:17:14.889127 17435 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6dca59d794084ef59f5a510c4be07fb4 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "6dca59d794084ef59f5a510c4be07fb4" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6dca59d794084ef59f5a510c4be07fb4" member_type: VOTER } }
I20260812 06:17:14.889247 17435 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6dca59d794084ef59f5a510c4be07fb4 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:14.889730 17436 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6dca59d794084ef59f5a510c4be07fb4 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 6dca59d794084ef59f5a510c4be07fb4. Latest consensus state: current_term: 1 leader_uuid: "6dca59d794084ef59f5a510c4be07fb4" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6dca59d794084ef59f5a510c4be07fb4" member_type: VOTER } }
I20260812 06:17:14.889811 17436 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6dca59d794084ef59f5a510c4be07fb4 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:14.890456 17439 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:14.891161 17439 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:14.891376 16906 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:14.893250 17439 catalog_manager.cc:1383] Generated new cluster ID: 6000a90d7ce34d6081ebb7d8afc91db9
I20260812 06:17:14.893313 17439 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:14.919585 17439 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:14.920537 17439 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:14.932161 17439 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 6dca59d794084ef59f5a510c4be07fb4: Generated new TSK 0
I20260812 06:17:14.932405 17439 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:14.956306 16906 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:14.958818 17464 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:14.958876 17466 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:14.958868 17462 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:14.959590 16906 server_base.cc:1061] running on GCE node
I20260812 06:17:14.959817 16906 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:14.959877 16906 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:14.959901 16906 hybrid_clock.cc:648] HybridClock initialized: now 1786515434959901 us; error 0 us; skew 500 ppm
I20260812 06:17:14.961097 16906 webserver.cc:533] Webserver started at http://127.16.130.129:39301/ using document root <none> and password file <none>
I20260812 06:17:14.961324 16906 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:14.961396 16906 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:14.961480 16906 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:14.962059 16906 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/instance:
uuid: "5d8f26e93a3045bb8d36a27d2623ddfc"
format_stamp: "Formatted at 2026-08-12 06:17:14 on dist-test-slave-z8x9"
I20260812 06:17:14.964174 16906 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.001s
I20260812 06:17:14.965812 17477 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:14.966150 16906 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.000s
I20260812 06:17:14.966220 16906 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root
uuid: "5d8f26e93a3045bb8d36a27d2623ddfc"
format_stamp: "Formatted at 2026-08-12 06:17:14 on dist-test-slave-z8x9"
I20260812 06:17:14.966321 16906 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:14.994462 16906 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:14.994933 16906 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:14.995282 16906 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:14.995940 16906 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:14.996021 16906 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:14.996088 16906 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:14.996140 16906 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:15.001153 16906 rpc_server.cc:307] RPC server started. Bound to: 127.16.130.129:37555
I20260812 06:17:15.002341 17613 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.16.130.129:37555 every 8 connection(s)
I20260812 06:17:15.012780 17614 heartbeater.cc:344] Connected to a master server at 127.16.130.190:37697
I20260812 06:17:15.013002 17614 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:15.013477 17614 heartbeater.cc:507] Master 127.16.130.190:37697 requested a full tablet report, sending...
I20260812 06:17:15.014516 17356 ts_manager.cc:194] Registered new tserver with Master: 5d8f26e93a3045bb8d36a27d2623ddfc (127.16.130.129:37555)
I20260812 06:17:15.015367 17356 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:39534
I20260812 06:17:15.015411 16906 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01344576s
I20260812 06:17:15.024531 17356 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:39546:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:15.035338 17536 tablet_service.cc:1511] Processing CreateTablet for tablet d85c9e1b7fbb4574826e9a3f8e28dd24 (DEFAULT_TABLE table=heavy-update-compaction-test [id=1d307dbc6c6341cc92d5fbc47b1e6468]), partition=
I20260812 06:17:15.036108 17536 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet d85c9e1b7fbb4574826e9a3f8e28dd24. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:15.039059 17636 tablet_bootstrap.cc:492] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Bootstrap starting.
I20260812 06:17:15.040553 17636 tablet_bootstrap.cc:654] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:15.042830 17636 tablet_bootstrap.cc:492] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: No bootstrap required, opened a new log
I20260812 06:17:15.042968 17636 ts_tablet_manager.cc:1403] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Time spent bootstrapping tablet: real 0.004s	user 0.002s	sys 0.000s
I20260812 06:17:15.043650 17636 raft_consensus.cc:359] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5d8f26e93a3045bb8d36a27d2623ddfc" member_type: VOTER last_known_addr { host: "127.16.130.129" port: 37555 } }
I20260812 06:17:15.043807 17636 raft_consensus.cc:385] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:15.043853 17636 raft_consensus.cc:740] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5d8f26e93a3045bb8d36a27d2623ddfc, State: Initialized, Role: FOLLOWER
I20260812 06:17:15.044057 17636 consensus_queue.cc:260] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc [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: "5d8f26e93a3045bb8d36a27d2623ddfc" member_type: VOTER last_known_addr { host: "127.16.130.129" port: 37555 } }
I20260812 06:17:15.044243 17636 raft_consensus.cc:399] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:15.044345 17636 raft_consensus.cc:493] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:15.044451 17636 raft_consensus.cc:3060] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:15.045799 17636 raft_consensus.cc:515] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5d8f26e93a3045bb8d36a27d2623ddfc" member_type: VOTER last_known_addr { host: "127.16.130.129" port: 37555 } }
I20260812 06:17:15.045979 17636 leader_election.cc:304] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc [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: 5d8f26e93a3045bb8d36a27d2623ddfc; no voters: 
I20260812 06:17:15.046233 17636 leader_election.cc:290] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:15.046631 17636 ts_tablet_manager.cc:1434] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Time spent starting tablet: real 0.004s	user 0.005s	sys 0.000s
I20260812 06:17:15.046715 17641 raft_consensus.cc:2804] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:15.046823 17614 heartbeater.cc:499] Master 127.16.130.190:37697 was elected leader, sending a full tablet report...
I20260812 06:17:15.047339 17641 raft_consensus.cc:697] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc [term 1 LEADER]: Becoming Leader. State: Replica: 5d8f26e93a3045bb8d36a27d2623ddfc, State: Running, Role: LEADER
I20260812 06:17:15.047683 17641 consensus_queue.cc:237] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc [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: "5d8f26e93a3045bb8d36a27d2623ddfc" member_type: VOTER last_known_addr { host: "127.16.130.129" port: 37555 } }
I20260812 06:17:15.049677 17356 catalog_manager.cc:5719] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc reported cstate change: term changed from 0 to 1, leader changed from <none> to 5d8f26e93a3045bb8d36a27d2623ddfc (127.16.130.129). New cstate: current_term: 1 leader_uuid: "5d8f26e93a3045bb8d36a27d2623ddfc" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5d8f26e93a3045bb8d36a27d2623ddfc" member_type: VOTER last_known_addr { host: "127.16.130.129" port: 37555 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:15.114622 16906 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.057s	user 0.016s	sys 0.007s
I20260812 06:17:15.252929 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushMRSOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=15.086190
I20260812 06:17:15.386345 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushMRSOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.133s	user 0.097s	sys 0.035s Metrics: {"bytes_written":8902493,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":189,"dirs.run_wall_time_us":905,"drs_written":1,"lbm_read_time_us":85,"lbm_reads_lt_1ms":4,"lbm_write_time_us":31654,"lbm_writes_lt_1ms":574,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":1536,"update_count":1085}
I20260812 06:17:15.387169 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling LogGCOp(d85c9e1b7fbb4574826e9a3f8e28dd24): free 11976772 bytes of WAL
I20260812 06:17:15.387401 17490 log_reader.cc:385] T d85c9e1b7fbb4574826e9a3f8e28dd24: removed 1 log segments from log reader
I20260812 06:17:15.387454 17490 log.cc:1079] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/d85c9e1b7fbb4574826e9a3f8e28dd24/wal-000000001 (ops 1-6)
I20260812 06:17:15.391357 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: LogGCOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.004s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:15.391746 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=2.188937
I20260812 06:17:15.408881 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.017s	user 0.007s	sys 0.007s Metrics: {"bytes_written":3405230,"delete_count":0,"lbm_write_time_us":5999,"lbm_writes_lt_1ms":86,"reinsert_count":0,"update_count":415}
I20260812 06:17:15.409543 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling UndoDeltaBlockGCOp(d85c9e1b7fbb4574826e9a3f8e28dd24): 12308958 bytes on disk
I20260812 06:17:15.410142 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: UndoDeltaBlockGCOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":116,"lbm_reads_lt_1ms":4}
I20260812 06:17:15.410753 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling MajorDeltaCompactionOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=1.000000
I20260812 06:17:15.587286 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: MajorDeltaCompactionOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.176s	user 0.111s	sys 0.056s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528886,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1141,"lbm_read_time_us":13864,"lbm_reads_lt_1ms":368,"lbm_write_time_us":24774,"lbm_writes_lt_1ms":343,"mutex_wait_us":114,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":385,"threads_started":5,"update_count":1500}
I20260812 06:17:15.588449 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=10.126437
I20260812 06:17:15.641397 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.053s	user 0.032s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18991,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:15.641947 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=2.188937
I20260812 06:17:15.657544 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.015s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5682,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.658203 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling MajorDeltaCompactionOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=1.000000
I20260812 06:17:15.817251 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: MajorDeltaCompactionOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.159s	user 0.112s	sys 0.044s 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":1392,"lbm_read_time_us":11614,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29211,"lbm_writes_lt_1ms":443,"mutex_wait_us":659,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":2000}
I20260812 06:17:15.818022 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=10.126437
I20260812 06:17:15.857867 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.037s	user 0.021s	sys 0.015s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16809,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:15.858441 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling MajorDeltaCompactionOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=1.000000
I20260812 06:17:15.983173 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: MajorDeltaCompactionOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.125s	user 0.087s	sys 0.021s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528782,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":275,"dirs.run_cpu_time_us":2885,"dirs.run_wall_time_us":23620,"lbm_read_time_us":7186,"lbm_reads_lt_1ms":363,"lbm_write_time_us":21123,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":1500}
I20260812 06:17:15.984187 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=10.126437
I20260812 06:17:16.036600 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.052s	user 0.022s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":22393,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:16.037375 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling MajorDeltaCompactionOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=1.000000
I20260812 06:17:16.183307 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: MajorDeltaCompactionOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.146s	user 0.116s	sys 0.029s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":962,"lbm_read_time_us":10578,"lbm_reads_lt_1ms":367,"lbm_write_time_us":23936,"lbm_writes_lt_1ms":343,"mutex_wait_us":322,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":1500}
I20260812 06:17:16.184144 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=10.126437
I20260812 06:17:16.238233 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.054s	user 0.034s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20623,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:16.238816 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=2.188937
I20260812 06:17:16.254099 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5562,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.254700 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling MajorDeltaCompactionOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=1.000000
I20260812 06:17:16.402560 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: MajorDeltaCompactionOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.148s	user 0.111s	sys 0.036s 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":11173,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28173,"lbm_writes_lt_1ms":443,"mutex_wait_us":61,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":22656,"update_count":2000}
I20260812 06:17:16.403348 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=10.126437
I20260812 06:17:16.459549 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.056s	user 0.031s	sys 0.013s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":20576,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:16.460122 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=2.188937
I20260812 06:17:16.476142 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.016s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5938,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.476753 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling MajorDeltaCompactionOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=1.000000
I20260812 06:17:16.608412 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: MajorDeltaCompactionOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.131s	user 0.097s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1810,"lbm_read_time_us":11690,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23254,"lbm_writes_lt_1ms":443,"mutex_wait_us":605,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2000}
I20260812 06:17:16.609306 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=7.149875
I20260812 06:17:16.634721 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.025s	user 0.011s	sys 0.012s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":10906,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:17:16.635273 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=2.188937
I20260812 06:17:16.659224 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.024s	user 0.010s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6413,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:16.659859 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling MajorDeltaCompactionOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=1.000000
I20260812 06:17:16.800212 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: MajorDeltaCompactionOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.140s	user 0.117s	sys 0.020s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528891,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":689,"lbm_read_time_us":9786,"lbm_reads_lt_1ms":372,"lbm_write_time_us":23370,"lbm_writes_lt_1ms":343,"mutex_wait_us":299,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:17:16.801024 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=7.149875
I20260812 06:17:16.834651 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.033s	user 0.023s	sys 0.009s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":14765,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:17:16.835237 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=2.188937
I20260812 06:17:16.851099 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5877,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:16.851861 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling MajorDeltaCompactionOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=1.000000
I20260812 06:17:17.004752 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: MajorDeltaCompactionOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.153s	user 0.104s	sys 0.039s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528891,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":582,"lbm_read_time_us":10455,"lbm_reads_lt_1ms":372,"lbm_write_time_us":25407,"lbm_writes_lt_1ms":343,"mutex_wait_us":239,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":1500}
I20260812 06:17:17.005615 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=10.126437
I20260812 06:17:17.059355 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.053s	user 0.027s	sys 0.016s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":22221,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:17:17.060017 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushMRSOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=1.000000
I20260812 06:17:17.116107 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushMRSOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.056s	user 0.031s	sys 0.007s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":100,"dirs.run_cpu_time_us":321,"dirs.run_wall_time_us":2078,"drs_written":1,"lbm_read_time_us":101,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2292,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:17.116832 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling LogGCOp(d85c9e1b7fbb4574826e9a3f8e28dd24): free 121006423 bytes of WAL
I20260812 06:17:17.117063 17490 log_reader.cc:385] T d85c9e1b7fbb4574826e9a3f8e28dd24: removed 12 log segments from log reader
I20260812 06:17:17.117111 17490 log.cc:1079] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/d85c9e1b7fbb4574826e9a3f8e28dd24/wal-000000002 (ops 7-11)
I20260812 06:17:17.117223 17490 log.cc:1079] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/d85c9e1b7fbb4574826e9a3f8e28dd24/wal-000000003 (ops 12-16)
I20260812 06:17:17.117265 17490 log.cc:1079] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/d85c9e1b7fbb4574826e9a3f8e28dd24/wal-000000004 (ops 17-20)
I20260812 06:17:17.117352 17490 log.cc:1079] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/d85c9e1b7fbb4574826e9a3f8e28dd24/wal-000000005 (ops 21-25)
I20260812 06:17:17.117394 17490 log.cc:1079] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/d85c9e1b7fbb4574826e9a3f8e28dd24/wal-000000006 (ops 26-30)
I20260812 06:17:17.117421 17490 log.cc:1079] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/d85c9e1b7fbb4574826e9a3f8e28dd24/wal-000000007 (ops 31-35)
I20260812 06:17:17.117470 17490 log.cc:1079] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/d85c9e1b7fbb4574826e9a3f8e28dd24/wal-000000008 (ops 36-40)
I20260812 06:17:17.117507 17490 log.cc:1079] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/d85c9e1b7fbb4574826e9a3f8e28dd24/wal-000000009 (ops 41-45)
I20260812 06:17:17.117568 17490 log.cc:1079] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/d85c9e1b7fbb4574826e9a3f8e28dd24/wal-000000010 (ops 46-50)
I20260812 06:17:17.117606 17490 log.cc:1079] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/d85c9e1b7fbb4574826e9a3f8e28dd24/wal-000000011 (ops 51-55)
I20260812 06:17:17.117666 17490 log.cc:1079] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/d85c9e1b7fbb4574826e9a3f8e28dd24/wal-000000012 (ops 56-60)
I20260812 06:17:17.117707 17490 log.cc:1079] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/d85c9e1b7fbb4574826e9a3f8e28dd24/wal-000000013 (ops 61-65)
I20260812 06:17:17.149797 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: LogGCOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.033s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:17:17.150357 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=7.149875
I20260812 06:17:17.183290 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.033s	user 0.020s	sys 0.009s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":13276,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:17:17.183780 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling LogGCOp(d85c9e1b7fbb4574826e9a3f8e28dd24): free 12017932 bytes of WAL
I20260812 06:17:17.183972 17490 log_reader.cc:385] T d85c9e1b7fbb4574826e9a3f8e28dd24: removed 1 log segments from log reader
I20260812 06:17:17.184019 17490 log.cc:1079] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/d85c9e1b7fbb4574826e9a3f8e28dd24/wal-000000014 (ops 66-70)
I20260812 06:17:17.187475 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: LogGCOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:17.187947 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=2.188937
I20260812 06:17:17.206599 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.018s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5646,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:17.207485 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling MajorDeltaCompactionOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=1.000000
I20260812 06:17:17.430507 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: MajorDeltaCompactionOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.223s	user 0.158s	sys 0.063s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836249,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":480,"lbm_read_time_us":16006,"lbm_reads_lt_1ms":665,"lbm_write_time_us":41716,"lbm_writes_lt_1ms":643,"mutex_wait_us":29,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14336,"thread_start_us":98,"threads_started":1,"update_count":3000}
I20260812 06:17:17.431260 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=18.063937
I20260812 06:17:17.505470 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.074s	user 0.048s	sys 0.024s Metrics: {"bytes_written":20512320,"delete_count":0,"lbm_write_time_us":32036,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:17.506348 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=3.181125
I20260812 06:17:17.531082 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.025s	user 0.014s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7785,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:17.531602 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=2.188937
I20260812 06:17:17.545894 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.014s	user 0.002s	sys 0.012s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5639,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:17.546504 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling UndoDeltaBlockGCOp(d85c9e1b7fbb4574826e9a3f8e28dd24): 483 bytes on disk
I20260812 06:17:17.547008 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: UndoDeltaBlockGCOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":83,"lbm_reads_lt_1ms":4}
I20260812 06:17:17.547622 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling MajorDeltaCompactionOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=1.000000
I20260812 06:17:17.774673 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: MajorDeltaCompactionOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.227s	user 0.183s	sys 0.036s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32938663,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":10420,"dirs.run_cpu_time_us":1532,"dirs.run_wall_time_us":17589,"lbm_read_time_us":15224,"lbm_reads_lt_1ms":773,"lbm_write_time_us":47513,"lbm_writes_lt_1ms":743,"mutex_wait_us":8281,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":3500}
I20260812 06:17:17.775521 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=14.095187
I20260812 06:17:17.829696 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.054s	user 0.032s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24138,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:17.830389 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=2.188937
I20260812 06:17:17.854725 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.024s	user 0.015s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6792,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.855332 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling MajorDeltaCompactionOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=1.000000
I20260812 06:17:18.047072 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: MajorDeltaCompactionOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.192s	user 0.129s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":49,"lbm_read_time_us":12246,"lbm_reads_lt_1ms":564,"lbm_write_time_us":37789,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14720,"thread_start_us":92,"threads_started":1,"update_count":2500}
I20260812 06:17:18.047814 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=14.095187
I20260812 06:17:18.100771 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.053s	user 0.036s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23273,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:18.101483 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling MajorDeltaCompactionOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=1.000000
I20260812 06:17:18.252238 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: MajorDeltaCompactionOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.150s	user 0.086s	sys 0.064s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631194,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":275,"lbm_read_time_us":11712,"lbm_reads_lt_1ms":463,"lbm_write_time_us":25964,"lbm_writes_lt_1ms":443,"mutex_wait_us":63,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":101376,"update_count":2000}
I20260812 06:17:18.253242 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=10.126437
I20260812 06:17:18.303339 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.050s	user 0.034s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19213,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:18.303973 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=2.188937
I20260812 06:17:18.325887 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.022s	user 0.005s	sys 0.016s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4240,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.326594 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling MajorDeltaCompactionOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=1.000000
I20260812 06:17:18.524484 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: MajorDeltaCompactionOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.198s	user 0.112s	sys 0.067s 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":334,"lbm_read_time_us":12018,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28985,"lbm_writes_lt_1ms":443,"mutex_wait_us":44,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:17:18.525195 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=10.126437
I20260812 06:17:18.580027 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.055s	user 0.021s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21101,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:18.580619 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=2.188937
I20260812 06:17:18.592523 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4415,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.593160 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling MajorDeltaCompactionOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=1.000000
I20260812 06:17:18.727628 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: MajorDeltaCompactionOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.134s	user 0.123s	sys 0.009s 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":177,"lbm_read_time_us":10127,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26818,"lbm_writes_lt_1ms":443,"mutex_wait_us":34,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":25216,"update_count":2000}
I20260812 06:17:18.728417 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=7.149875
I20260812 06:17:18.758349 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.030s	user 0.017s	sys 0.011s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":11882,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":212,"reinsert_count":0,"update_count":1050}
I20260812 06:17:18.758963 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=2.188937
I20260812 06:17:18.780155 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.021s	user 0.016s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6792,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:18.780665 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushMRSOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=1.000000
I20260812 06:17:18.837101 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushMRSOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.056s	user 0.033s	sys 0.004s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":81,"dirs.run_cpu_time_us":260,"dirs.run_wall_time_us":1382,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2079,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:18.838308 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling LogGCOp(d85c9e1b7fbb4574826e9a3f8e28dd24): free 121006436 bytes of WAL
I20260812 06:17:18.838583 17490 log_reader.cc:385] T d85c9e1b7fbb4574826e9a3f8e28dd24: removed 12 log segments from log reader
I20260812 06:17:18.838649 17490 log.cc:1079] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/d85c9e1b7fbb4574826e9a3f8e28dd24/wal-000000015 (ops 71-75)
I20260812 06:17:18.838692 17490 log.cc:1079] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/d85c9e1b7fbb4574826e9a3f8e28dd24/wal-000000016 (ops 76-80)
I20260812 06:17:18.838719 17490 log.cc:1079] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/d85c9e1b7fbb4574826e9a3f8e28dd24/wal-000000017 (ops 81-85)
I20260812 06:17:18.838745 17490 log.cc:1079] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/d85c9e1b7fbb4574826e9a3f8e28dd24/wal-000000018 (ops 86-90)
I20260812 06:17:18.838773 17490 log.cc:1079] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/d85c9e1b7fbb4574826e9a3f8e28dd24/wal-000000019 (ops 91-94)
I20260812 06:17:18.838797 17490 log.cc:1079] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/d85c9e1b7fbb4574826e9a3f8e28dd24/wal-000000020 (ops 95-99)
I20260812 06:17:18.838861 17490 log.cc:1079] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/d85c9e1b7fbb4574826e9a3f8e28dd24/wal-000000021 (ops 100-104)
I20260812 06:17:18.838900 17490 log.cc:1079] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/d85c9e1b7fbb4574826e9a3f8e28dd24/wal-000000022 (ops 105-109)
I20260812 06:17:18.838927 17490 log.cc:1079] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/d85c9e1b7fbb4574826e9a3f8e28dd24/wal-000000023 (ops 110-114)
I20260812 06:17:18.838955 17490 log.cc:1079] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/d85c9e1b7fbb4574826e9a3f8e28dd24/wal-000000024 (ops 115-119)
I20260812 06:17:18.839018 17490 log.cc:1079] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/d85c9e1b7fbb4574826e9a3f8e28dd24/wal-000000025 (ops 120-124)
I20260812 06:17:18.839061 17490 log.cc:1079] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/d85c9e1b7fbb4574826e9a3f8e28dd24/wal-000000026 (ops 125-129)
I20260812 06:17:18.871443 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: LogGCOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.033s	user 0.002s	sys 0.028s Metrics: {}
I20260812 06:17:18.872017 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=7.149875
I20260812 06:17:18.901443 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.029s	user 0.008s	sys 0.021s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":12686,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:17:18.902088 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling UndoDeltaBlockGCOp(d85c9e1b7fbb4574826e9a3f8e28dd24): 471 bytes on disk
I20260812 06:17:18.902532 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: UndoDeltaBlockGCOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:17:18.903076 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=2.188937
I20260812 06:17:18.926368 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.023s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5243,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:18.927003 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=2.188937
I20260812 06:17:18.943346 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6094,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.943935 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling MajorDeltaCompactionOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=1.000000
I20260812 06:17:19.170387 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: MajorDeltaCompactionOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.226s	user 0.147s	sys 0.076s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32938887,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":3944,"lbm_read_time_us":15749,"lbm_reads_lt_1ms":775,"lbm_write_time_us":48339,"lbm_writes_lt_1ms":743,"mutex_wait_us":39,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":15232,"thread_start_us":106,"threads_started":1,"update_count":3500}
I20260812 06:17:19.171144 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=18.063937
I20260812 06:17:19.232617 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.061s	user 0.029s	sys 0.029s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":29108,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:19.233328 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=2.188937
I20260812 06:17:19.247606 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.014s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5542,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.248095 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling MajorDeltaCompactionOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=1.000000
I20260812 06:17:19.456852 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: MajorDeltaCompactionOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.209s	user 0.164s	sys 0.036s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836138,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":549,"lbm_read_time_us":13163,"lbm_reads_lt_1ms":668,"lbm_write_time_us":43239,"lbm_writes_lt_1ms":643,"mutex_wait_us":335,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":3000}
I20260812 06:17:19.457603 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=18.063937
I20260812 06:17:19.529505 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.072s	user 0.031s	sys 0.039s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":33592,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:19.530503 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=2.188937
I20260812 06:17:19.559645 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.029s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5841,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.560281 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=2.188937
I20260812 06:17:19.576941 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5996,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.577628 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling MajorDeltaCompactionOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=1.000000
I20260812 06:17:19.777400 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: MajorDeltaCompactionOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.200s	user 0.155s	sys 0.039s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32938669,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":2185,"lbm_read_time_us":17429,"lbm_reads_lt_1ms":773,"lbm_write_time_us":41909,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":3500}
I20260812 06:17:19.778286 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=14.095187
I20260812 06:17:19.829969 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.052s	user 0.018s	sys 0.033s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23732,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:19.830631 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=2.188937
I20260812 06:17:19.859551 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.029s	user 0.004s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7120,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.860069 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=2.188937
I20260812 06:17:19.875370 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6010,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.875916 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling MajorDeltaCompactionOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=1.000000
I20260812 06:17:20.066305 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: MajorDeltaCompactionOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.190s	user 0.156s	sys 0.031s 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":660,"lbm_read_time_us":16068,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35991,"lbm_writes_lt_1ms":643,"mutex_wait_us":57,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":16896,"update_count":3000}
I20260812 06:17:20.067049 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=11.118625
I20260812 06:17:20.121098 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.054s	user 0.026s	sys 0.018s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":22190,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:20.121721 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=2.188937
I20260812 06:17:20.139405 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.017s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6966,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.139958 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=2.188937
I20260812 06:17:20.153848 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5156,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:20.154606 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling MajorDeltaCompactionOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=1.000000
I20260812 06:17:20.344329 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: MajorDeltaCompactionOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.190s	user 0.134s	sys 0.036s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733835,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":756,"lbm_read_time_us":12080,"lbm_reads_lt_1ms":573,"lbm_write_time_us":33613,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":2500}
I20260812 06:17:20.345155 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=14.095187
I20260812 06:17:20.412897 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.067s	user 0.034s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23976,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:20.413636 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=2.188937
I20260812 06:17:20.427891 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.014s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4529,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.428844 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushMRSOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=1.000000
I20260812 06:17:20.469453 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushMRSOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.040s	user 0.040s	sys 0.000s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":283,"dirs.run_wall_time_us":1842,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1846,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:20.470201 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling LogGCOp(d85c9e1b7fbb4574826e9a3f8e28dd24): free 133024594 bytes of WAL
I20260812 06:17:20.470464 17490 log_reader.cc:385] T d85c9e1b7fbb4574826e9a3f8e28dd24: removed 13 log segments from log reader
I20260812 06:17:20.470535 17490 log.cc:1079] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/d85c9e1b7fbb4574826e9a3f8e28dd24/wal-000000027 (ops 130-134)
I20260812 06:17:20.470590 17490 log.cc:1079] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/d85c9e1b7fbb4574826e9a3f8e28dd24/wal-000000028 (ops 135-139)
I20260812 06:17:20.470675 17490 log.cc:1079] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/d85c9e1b7fbb4574826e9a3f8e28dd24/wal-000000029 (ops 140-144)
I20260812 06:17:20.470723 17490 log.cc:1079] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/d85c9e1b7fbb4574826e9a3f8e28dd24/wal-000000030 (ops 145-148)
I20260812 06:17:20.470763 17490 log.cc:1079] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/d85c9e1b7fbb4574826e9a3f8e28dd24/wal-000000031 (ops 149-153)
I20260812 06:17:20.470803 17490 log.cc:1079] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/d85c9e1b7fbb4574826e9a3f8e28dd24/wal-000000032 (ops 154-158)
I20260812 06:17:20.470840 17490 log.cc:1079] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/d85c9e1b7fbb4574826e9a3f8e28dd24/wal-000000033 (ops 159-163)
I20260812 06:17:20.470880 17490 log.cc:1079] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/d85c9e1b7fbb4574826e9a3f8e28dd24/wal-000000034 (ops 164-168)
I20260812 06:17:20.470918 17490 log.cc:1079] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/d85c9e1b7fbb4574826e9a3f8e28dd24/wal-000000035 (ops 169-173)
I20260812 06:17:20.470956 17490 log.cc:1079] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/d85c9e1b7fbb4574826e9a3f8e28dd24/wal-000000036 (ops 174-178)
I20260812 06:17:20.470995 17490 log.cc:1079] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/d85c9e1b7fbb4574826e9a3f8e28dd24/wal-000000037 (ops 179-183)
I20260812 06:17:20.471033 17490 log.cc:1079] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/d85c9e1b7fbb4574826e9a3f8e28dd24/wal-000000038 (ops 184-188)
I20260812 06:17:20.471072 17490 log.cc:1079] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: Deleting log segment in path: /tmp/dist-test-task7vpUui/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515428796425-16906-0/minicluster-data/ts-0-root/wals/d85c9e1b7fbb4574826e9a3f8e28dd24/wal-000000039 (ops 189-193)
I20260812 06:17:20.503751 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: LogGCOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.033s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:17:20.504456 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=4.173312
I20260812 06:17:20.528262 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.023s	user 0.017s	sys 0.004s Metrics: {"bytes_written":6153870,"delete_count":0,"lbm_write_time_us":9444,"lbm_writes_lt_1ms":153,"reinsert_count":0,"update_count":750}
I20260812 06:17:20.528851 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=1.000000
I20260812 06:17:20.537309 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: FlushDeltaMemStoresOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.008s	user 0.005s	sys 0.003s Metrics: {"bytes_written":2051402,"delete_count":0,"lbm_write_time_us":2393,"lbm_writes_lt_1ms":53,"reinsert_count":0,"update_count":250}
I20260812 06:17:20.537911 17615 maintenance_manager.cc:419] P 5d8f26e93a3045bb8d36a27d2623ddfc: Scheduling MajorDeltaCompactionOp(d85c9e1b7fbb4574826e9a3f8e28dd24): perf score=1.000000
I20260812 06:17:20.619091 16906 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.504s	user 2.022s	sys 0.121s
I20260812 06:17:20.741210 16906 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.122s	user 0.001s	sys 0.000s
I20260812 06:17:20.741950 16906 tablet_server.cc:179] TabletServer@127.16.130.129:0 shutting down...
I20260812 06:17:20.777505 17490 maintenance_manager.cc:643] P 5d8f26e93a3045bb8d36a27d2623ddfc: MajorDeltaCompactionOp(d85c9e1b7fbb4574826e9a3f8e28dd24) complete. Timing: real 0.239s	user 0.178s	sys 0.060s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938733,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1731,"lbm_read_time_us":16442,"lbm_reads_lt_1ms":770,"lbm_write_time_us":46903,"lbm_writes_lt_1ms":743,"mutex_wait_us":588,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3840,"thread_start_us":86,"threads_started":1,"update_count":3500}
I20260812 06:17:20.779210 16906 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:20.779496 16906 tablet_replica.cc:333] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc: stopping tablet replica
I20260812 06:17:20.779662 16906 raft_consensus.cc:2243] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:20.779868 16906 raft_consensus.cc:2272] T d85c9e1b7fbb4574826e9a3f8e28dd24 P 5d8f26e93a3045bb8d36a27d2623ddfc [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:20.786139 16906 tablet_server.cc:196] TabletServer@127.16.130.129:0 shutdown complete.
I20260812 06:17:20.837728 16906 master.cc:562] Master@127.16.130.190:37697 shutting down...
I20260812 06:17:20.842110 16906 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 6dca59d794084ef59f5a510c4be07fb4 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:20.842378 16906 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 6dca59d794084ef59f5a510c4be07fb4 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:20.842470 16906 tablet_replica.cc:333] T 00000000000000000000000000000000 P 6dca59d794084ef59f5a510c4be07fb4: stopping tablet replica
I20260812 06:17:20.855391 16906 master.cc:584] Master@127.16.130.190:37697 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (6110 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (12140 ms total)

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