[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:19:42.831231 31750 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.31.1.190:39251
I20260812 06:19:42.832311 31750 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:19:42.832947 31750 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:42.840101 31759 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:42.840111 31757 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:42.840126 31762 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:42.840833 31750 server_base.cc:1061] running on GCE node
I20260812 06:19:42.841351 31750 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:42.841481 31750 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:42.841527 31750 hybrid_clock.cc:648] HybridClock initialized: now 1786515582841523 us; error 0 us; skew 500 ppm
I20260812 06:19:42.843551 31750 webserver.cc:533] Webserver started at http://127.31.1.190:34939/ using document root <none> and password file <none>
I20260812 06:19:42.844233 31750 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:42.844350 31750 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:42.844647 31750 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:42.846475 31750 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/master-0-root/instance:
uuid: "ae896aa257e9472f82373c886d7a0826"
format_stamp: "Formatted at 2026-08-12 06:19:42 on dist-test-slave-g170"
I20260812 06:19:42.850513 31750 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.005s	sys 0.000s
I20260812 06:19:42.852903 31771 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:42.854043 31750 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:42.854259 31750 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/master-0-root
uuid: "ae896aa257e9472f82373c886d7a0826"
format_stamp: "Formatted at 2026-08-12 06:19:42 on dist-test-slave-g170"
I20260812 06:19:42.854398 31750 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:42.869083 31750 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:42.869745 31750 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:19:42.869926 31750 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:42.877827 31750 rpc_server.cc:307] RPC server started. Bound to: 127.31.1.190:39251
I20260812 06:19:42.877910 31873 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.31.1.190:39251 every 8 connection(s)
I20260812 06:19:42.880245 31874 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:42.885592 31874 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ae896aa257e9472f82373c886d7a0826: Bootstrap starting.
I20260812 06:19:42.887966 31874 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P ae896aa257e9472f82373c886d7a0826: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:42.888870 31874 log.cc:826] T 00000000000000000000000000000000 P ae896aa257e9472f82373c886d7a0826: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:42.890497 31874 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ae896aa257e9472f82373c886d7a0826: No bootstrap required, opened a new log
I20260812 06:19:42.893287 31874 raft_consensus.cc:359] T 00000000000000000000000000000000 P ae896aa257e9472f82373c886d7a0826 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ae896aa257e9472f82373c886d7a0826" member_type: VOTER }
I20260812 06:19:42.893442 31874 raft_consensus.cc:385] T 00000000000000000000000000000000 P ae896aa257e9472f82373c886d7a0826 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:42.893492 31874 raft_consensus.cc:740] T 00000000000000000000000000000000 P ae896aa257e9472f82373c886d7a0826 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ae896aa257e9472f82373c886d7a0826, State: Initialized, Role: FOLLOWER
I20260812 06:19:42.893985 31874 consensus_queue.cc:260] T 00000000000000000000000000000000 P ae896aa257e9472f82373c886d7a0826 [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: "ae896aa257e9472f82373c886d7a0826" member_type: VOTER }
I20260812 06:19:42.894111 31874 raft_consensus.cc:399] T 00000000000000000000000000000000 P ae896aa257e9472f82373c886d7a0826 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:42.894152 31874 raft_consensus.cc:493] T 00000000000000000000000000000000 P ae896aa257e9472f82373c886d7a0826 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:42.894244 31874 raft_consensus.cc:3060] T 00000000000000000000000000000000 P ae896aa257e9472f82373c886d7a0826 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:42.894956 31874 raft_consensus.cc:515] T 00000000000000000000000000000000 P ae896aa257e9472f82373c886d7a0826 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ae896aa257e9472f82373c886d7a0826" member_type: VOTER }
I20260812 06:19:42.895325 31874 leader_election.cc:304] T 00000000000000000000000000000000 P ae896aa257e9472f82373c886d7a0826 [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: ae896aa257e9472f82373c886d7a0826; no voters: 
I20260812 06:19:42.895594 31874 leader_election.cc:290] T 00000000000000000000000000000000 P ae896aa257e9472f82373c886d7a0826 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:42.895744 31877 raft_consensus.cc:2804] T 00000000000000000000000000000000 P ae896aa257e9472f82373c886d7a0826 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:42.896009 31877 raft_consensus.cc:697] T 00000000000000000000000000000000 P ae896aa257e9472f82373c886d7a0826 [term 1 LEADER]: Becoming Leader. State: Replica: ae896aa257e9472f82373c886d7a0826, State: Running, Role: LEADER
I20260812 06:19:42.896443 31877 consensus_queue.cc:237] T 00000000000000000000000000000000 P ae896aa257e9472f82373c886d7a0826 [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: "ae896aa257e9472f82373c886d7a0826" member_type: VOTER }
I20260812 06:19:42.896579 31874 sys_catalog.cc:565] T 00000000000000000000000000000000 P ae896aa257e9472f82373c886d7a0826 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:42.898514 31880 sys_catalog.cc:455] T 00000000000000000000000000000000 P ae896aa257e9472f82373c886d7a0826 [sys.catalog]: SysCatalogTable state changed. Reason: New leader ae896aa257e9472f82373c886d7a0826. Latest consensus state: current_term: 1 leader_uuid: "ae896aa257e9472f82373c886d7a0826" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ae896aa257e9472f82373c886d7a0826" member_type: VOTER } }
I20260812 06:19:42.898488 31879 sys_catalog.cc:455] T 00000000000000000000000000000000 P ae896aa257e9472f82373c886d7a0826 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "ae896aa257e9472f82373c886d7a0826" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ae896aa257e9472f82373c886d7a0826" member_type: VOTER } }
I20260812 06:19:42.898666 31879 sys_catalog.cc:458] T 00000000000000000000000000000000 P ae896aa257e9472f82373c886d7a0826 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:42.898934 31750 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:42.898666 31880 sys_catalog.cc:458] T 00000000000000000000000000000000 P ae896aa257e9472f82373c886d7a0826 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:42.899132 31903 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:42.901438 31903 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:42.905949 31903 catalog_manager.cc:1383] Generated new cluster ID: 867d0c05e05948d2aba6540b056a5f2a
I20260812 06:19:42.906023 31903 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:42.920996 31903 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:42.921849 31903 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:42.930171 31903 catalog_manager.cc:6092] T 00000000000000000000000000000000 P ae896aa257e9472f82373c886d7a0826: Generated new TSK 0
I20260812 06:19:42.930859 31903 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:42.963704 31750 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:42.966446 31914 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:42.966477 31919 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:42.966701 31916 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:42.967162 31750 server_base.cc:1061] running on GCE node
I20260812 06:19:42.967343 31750 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:42.967387 31750 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:42.967409 31750 hybrid_clock.cc:648] HybridClock initialized: now 1786515582967409 us; error 0 us; skew 500 ppm
I20260812 06:19:42.968482 31750 webserver.cc:533] Webserver started at http://127.31.1.129:34839/ using document root <none> and password file <none>
I20260812 06:19:42.968652 31750 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:42.968716 31750 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:42.968819 31750 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:42.969272 31750 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/instance:
uuid: "562bb2f18ea2421b868ebb81c9ad8dd6"
format_stamp: "Formatted at 2026-08-12 06:19:42 on dist-test-slave-g170"
I20260812 06:19:42.971130 31750 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:42.972257 31932 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:42.972541 31750 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:42.972620 31750 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root
uuid: "562bb2f18ea2421b868ebb81c9ad8dd6"
format_stamp: "Formatted at 2026-08-12 06:19:42 on dist-test-slave-g170"
I20260812 06:19:42.972690 31750 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:42.979928 31750 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:42.980355 31750 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:42.980863 31750 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:42.981850 31750 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:42.981917 31750 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:42.981971 31750 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:42.982003 31750 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:42.988706 31750 rpc_server.cc:307] RPC server started. Bound to: 127.31.1.129:45565
I20260812 06:19:42.988729 32056 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.31.1.129:45565 every 8 connection(s)
I20260812 06:19:42.998682 32058 heartbeater.cc:344] Connected to a master server at 127.31.1.190:39251
I20260812 06:19:42.998991 32058 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:42.999455 32058 heartbeater.cc:507] Master 127.31.1.190:39251 requested a full tablet report, sending...
I20260812 06:19:43.001060 31809 ts_manager.cc:194] Registered new tserver with Master: 562bb2f18ea2421b868ebb81c9ad8dd6 (127.31.1.129:45565)
I20260812 06:19:43.001817 31750 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012421966s
I20260812 06:19:43.002532 31809 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:47714
I20260812 06:19:43.012113 31809 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:47720:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:43.027804 31995 tablet_service.cc:1511] Processing CreateTablet for tablet 00f76ba3fdfb42e68b2a22baf2c97727 (DEFAULT_TABLE table=heavy-update-compaction-test [id=5fc3a21338ad4b7f8276ad6ccadc5bf4]), partition=
I20260812 06:19:43.028307 31995 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00f76ba3fdfb42e68b2a22baf2c97727. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:43.030772 32082 tablet_bootstrap.cc:492] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Bootstrap starting.
I20260812 06:19:43.031828 32082 tablet_bootstrap.cc:654] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:43.033012 32082 tablet_bootstrap.cc:492] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: No bootstrap required, opened a new log
I20260812 06:19:43.033134 32082 ts_tablet_manager.cc:1403] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:43.033589 32082 raft_consensus.cc:359] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "562bb2f18ea2421b868ebb81c9ad8dd6" member_type: VOTER last_known_addr { host: "127.31.1.129" port: 45565 } }
I20260812 06:19:43.033730 32082 raft_consensus.cc:385] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:43.033785 32082 raft_consensus.cc:740] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 562bb2f18ea2421b868ebb81c9ad8dd6, State: Initialized, Role: FOLLOWER
I20260812 06:19:43.033932 32082 consensus_queue.cc:260] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6 [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: "562bb2f18ea2421b868ebb81c9ad8dd6" member_type: VOTER last_known_addr { host: "127.31.1.129" port: 45565 } }
I20260812 06:19:43.034058 32082 raft_consensus.cc:399] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:43.034109 32082 raft_consensus.cc:493] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:43.034164 32082 raft_consensus.cc:3060] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:43.035125 32082 raft_consensus.cc:515] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "562bb2f18ea2421b868ebb81c9ad8dd6" member_type: VOTER last_known_addr { host: "127.31.1.129" port: 45565 } }
I20260812 06:19:43.035276 32082 leader_election.cc:304] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6 [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: 562bb2f18ea2421b868ebb81c9ad8dd6; no voters: 
I20260812 06:19:43.035530 32082 leader_election.cc:290] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:43.035624 32084 raft_consensus.cc:2804] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:43.035807 32084 raft_consensus.cc:697] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6 [term 1 LEADER]: Becoming Leader. State: Replica: 562bb2f18ea2421b868ebb81c9ad8dd6, State: Running, Role: LEADER
I20260812 06:19:43.035936 32082 ts_tablet_manager.cc:1434] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:19:43.036019 32084 consensus_queue.cc:237] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6 [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: "562bb2f18ea2421b868ebb81c9ad8dd6" member_type: VOTER last_known_addr { host: "127.31.1.129" port: 45565 } }
I20260812 06:19:43.036202 32058 heartbeater.cc:499] Master 127.31.1.190:39251 was elected leader, sending a full tablet report...
I20260812 06:19:43.038790 31809 catalog_manager.cc:5719] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6 reported cstate change: term changed from 0 to 1, leader changed from <none> to 562bb2f18ea2421b868ebb81c9ad8dd6 (127.31.1.129). New cstate: current_term: 1 leader_uuid: "562bb2f18ea2421b868ebb81c9ad8dd6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "562bb2f18ea2421b868ebb81c9ad8dd6" member_type: VOTER last_known_addr { host: "127.31.1.129" port: 45565 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:43.112922 31750 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.065s	user 0.025s	sys 0.008s
I20260812 06:19:43.240085 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushMRSOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=15.086190
I20260812 06:19:43.424441 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushMRSOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.184s	user 0.140s	sys 0.035s Metrics: {"bytes_written":12635675,"cfile_init":1,"compiler_manager_pool.queue_time_us":188,"delete_count":0,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":196,"dirs.run_wall_time_us":1102,"drs_written":1,"lbm_read_time_us":92,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42103,"lbm_writes_lt_1ms":675,"mutex_wait_us":442,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":172800,"thread_start_us":119,"threads_started":1,"update_count":1540}
I20260812 06:19:43.426054 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling LogGCOp(00f76ba3fdfb42e68b2a22baf2c97727): free 20743880 bytes of WAL
I20260812 06:19:43.426503 31944 log_reader.cc:385] T 00f76ba3fdfb42e68b2a22baf2c97727: removed 2 log segments from log reader
I20260812 06:19:43.426656 31944 log.cc:1079] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/00f76ba3fdfb42e68b2a22baf2c97727/wal-000000001 (ops 1-6)
I20260812 06:19:43.426792 31944 log.cc:1079] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/00f76ba3fdfb42e68b2a22baf2c97727/wal-000000002 (ops 7-11)
I20260812 06:19:43.432191 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: LogGCOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.006s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:43.432565 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling UndoDeltaBlockGCOp(00f76ba3fdfb42e68b2a22baf2c97727): 12719217 bytes on disk
I20260812 06:19:43.433182 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: UndoDeltaBlockGCOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:19:43.433583 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=2.188937
I20260812 06:19:43.454901 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.021s	user 0.002s	sys 0.007s Metrics: {"bytes_written":3774459,"delete_count":0,"lbm_write_time_us":4066,"lbm_writes_lt_1ms":95,"reinsert_count":0,"update_count":460}
I20260812 06:19:43.455559 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=2.188937
I20260812 06:19:43.469920 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5571,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:43.470484 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling MajorDeltaCompactionOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=1.000000
I20260812 06:19:43.626163 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: MajorDeltaCompactionOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.155s	user 0.108s	sys 0.047s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24364539,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":72,"lbm_read_time_us":11948,"lbm_reads_lt_1ms":559,"lbm_write_time_us":30424,"lbm_writes_lt_1ms":533,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":1792,"thread_start_us":293,"threads_started":5,"update_count":2450}
I20260812 06:19:43.626601 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=10.126437
I20260812 06:19:43.678290 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.051s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18322,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:43.678781 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=2.188937
I20260812 06:19:43.690615 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4238,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.691087 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling MajorDeltaCompactionOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=1.000000
I20260812 06:19:43.823755 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: MajorDeltaCompactionOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.132s	user 0.120s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":370,"lbm_read_time_us":11060,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25721,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":43264,"update_count":2000}
I20260812 06:19:43.824504 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=10.126437
I20260812 06:19:43.872949 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.048s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17526,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:43.873392 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=2.188937
I20260812 06:19:43.884536 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4253,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.885279 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling MajorDeltaCompactionOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=1.000000
I20260812 06:19:44.005884 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: MajorDeltaCompactionOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.120s	user 0.095s	sys 0.026s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":234,"lbm_read_time_us":8611,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25323,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":20992,"update_count":2000}
I20260812 06:19:44.006474 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=10.126437
I20260812 06:19:44.065050 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.058s	user 0.031s	sys 0.019s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16802,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:44.065631 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=2.188937
I20260812 06:19:44.083465 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.018s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6627,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.084015 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling MajorDeltaCompactionOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=1.000000
I20260812 06:19:44.235188 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: MajorDeltaCompactionOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.151s	user 0.104s	sys 0.046s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":711,"lbm_read_time_us":12362,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25148,"lbm_writes_lt_1ms":443,"mutex_wait_us":46,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16256,"update_count":2000}
I20260812 06:19:44.235826 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=10.126437
I20260812 06:19:44.276918 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.041s	user 0.027s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17466,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:44.277560 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=2.188937
I20260812 06:19:44.289410 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4394,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.290128 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling MajorDeltaCompactionOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=1.000000
I20260812 06:19:44.416121 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: MajorDeltaCompactionOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.126s	user 0.101s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":297,"lbm_read_time_us":10117,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24315,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2000}
I20260812 06:19:44.416850 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=10.126437
I20260812 06:19:44.456272 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.039s	user 0.032s	sys 0.004s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17667,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:44.456830 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=2.188937
I20260812 06:19:44.469050 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.012s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4626,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.469528 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling MajorDeltaCompactionOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=1.000000
I20260812 06:19:44.592294 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: MajorDeltaCompactionOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.123s	user 0.090s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1150,"lbm_read_time_us":9513,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24787,"lbm_writes_lt_1ms":443,"mutex_wait_us":379,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2000}
I20260812 06:19:44.593008 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=10.126437
I20260812 06:19:44.639791 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.047s	user 0.023s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15552,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:44.640281 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=2.188937
I20260812 06:19:44.652936 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.012s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4846,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.661327 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushMRSOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=1.000000
I20260812 06:19:44.686790 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushMRSOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.025s	user 0.019s	sys 0.004s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":51,"dirs.run_cpu_time_us":214,"dirs.run_wall_time_us":1324,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1557,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:44.687559 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling LogGCOp(00f76ba3fdfb42e68b2a22baf2c97727): free 112239268 bytes of WAL
I20260812 06:19:44.687795 31944 log_reader.cc:385] T 00f76ba3fdfb42e68b2a22baf2c97727: removed 11 log segments from log reader
I20260812 06:19:44.687839 31944 log.cc:1079] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/00f76ba3fdfb42e68b2a22baf2c97727/wal-000000003 (ops 12-16)
I20260812 06:19:44.687868 31944 log.cc:1079] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/00f76ba3fdfb42e68b2a22baf2c97727/wal-000000004 (ops 17-21)
I20260812 06:19:44.687912 31944 log.cc:1079] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/00f76ba3fdfb42e68b2a22baf2c97727/wal-000000005 (ops 22-26)
I20260812 06:19:44.687953 31944 log.cc:1079] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/00f76ba3fdfb42e68b2a22baf2c97727/wal-000000006 (ops 27-31)
I20260812 06:19:44.687997 31944 log.cc:1079] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/00f76ba3fdfb42e68b2a22baf2c97727/wal-000000007 (ops 32-36)
I20260812 06:19:44.688038 31944 log.cc:1079] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/00f76ba3fdfb42e68b2a22baf2c97727/wal-000000008 (ops 37-41)
I20260812 06:19:44.688086 31944 log.cc:1079] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/00f76ba3fdfb42e68b2a22baf2c97727/wal-000000009 (ops 42-46)
I20260812 06:19:44.688131 31944 log.cc:1079] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/00f76ba3fdfb42e68b2a22baf2c97727/wal-000000010 (ops 47-51)
I20260812 06:19:44.688158 31944 log.cc:1079] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/00f76ba3fdfb42e68b2a22baf2c97727/wal-000000011 (ops 52-56)
I20260812 06:19:44.688196 31944 log.cc:1079] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/00f76ba3fdfb42e68b2a22baf2c97727/wal-000000012 (ops 57-60)
I20260812 06:19:44.688233 31944 log.cc:1079] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/00f76ba3fdfb42e68b2a22baf2c97727/wal-000000013 (ops 61-65)
I20260812 06:19:44.715723 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: LogGCOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:19:44.716187 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=3.181125
I20260812 06:19:44.735721 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.019s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7243,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:44.736279 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=2.188937
I20260812 06:19:44.745798 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.009s	user 0.008s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3537,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:44.746256 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling UndoDeltaBlockGCOp(00f76ba3fdfb42e68b2a22baf2c97727): 462 bytes on disk
I20260812 06:19:44.746670 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: UndoDeltaBlockGCOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:19:44.747184 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling MajorDeltaCompactionOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=1.000000
I20260812 06:19:44.943536 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: MajorDeltaCompactionOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.196s	user 0.131s	sys 0.052s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877326,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":958,"lbm_read_time_us":14227,"lbm_reads_lt_1ms":674,"lbm_write_time_us":38332,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1152,"thread_start_us":82,"threads_started":1,"update_count":3000}
I20260812 06:19:44.944061 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=14.095187
I20260812 06:19:45.009954 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.066s	user 0.036s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":32304,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:45.010491 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=2.188937
I20260812 06:19:45.028487 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.018s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6303,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.029162 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling MajorDeltaCompactionOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=1.000000
I20260812 06:19:45.207437 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: MajorDeltaCompactionOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.178s	user 0.128s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":923,"lbm_read_time_us":10041,"lbm_reads_lt_1ms":564,"lbm_write_time_us":34690,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:45.208489 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=14.095187
I20260812 06:19:45.270036 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.057s	user 0.036s	sys 0.020s Metrics: {"bytes_written":16820141,"delete_count":0,"lbm_write_time_us":25327,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:45.270533 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=2.188937
I20260812 06:19:45.291476 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.021s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4622,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.291927 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=2.188937
I20260812 06:19:45.302379 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3991,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:45.302821 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling MajorDeltaCompactionOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=1.000000
I20260812 06:19:45.470312 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: MajorDeltaCompactionOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.167s	user 0.135s	sys 0.032s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877205,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":916,"lbm_read_time_us":12091,"lbm_reads_lt_1ms":673,"lbm_write_time_us":34552,"lbm_writes_lt_1ms":643,"mutex_wait_us":85,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":3000}
I20260812 06:19:45.470866 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=14.095187
I20260812 06:19:45.519281 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.048s	user 0.038s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21214,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:45.519840 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=2.188937
I20260812 06:19:45.530407 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4135,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.530881 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling MajorDeltaCompactionOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=1.000000
I20260812 06:19:45.702936 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: MajorDeltaCompactionOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.172s	user 0.109s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":195,"lbm_read_time_us":10957,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32516,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:19:45.703816 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=14.095187
I20260812 06:19:45.768515 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.064s	user 0.038s	sys 0.011s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":23488,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:45.769089 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=2.188937
I20260812 06:19:45.785333 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6077,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.786041 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling MajorDeltaCompactionOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=1.000000
I20260812 06:19:45.951202 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: MajorDeltaCompactionOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.165s	user 0.121s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":388,"lbm_read_time_us":10827,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30847,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:45.951882 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=11.118625
I20260812 06:19:46.001523 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.049s	user 0.026s	sys 0.023s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17579,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:46.002203 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=2.188937
I20260812 06:19:46.018241 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5832,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:46.018889 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling MajorDeltaCompactionOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=1.000000
I20260812 06:19:46.171090 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: MajorDeltaCompactionOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.152s	user 0.095s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":570,"lbm_read_time_us":11237,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24184,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15488,"update_count":2000}
I20260812 06:19:46.171945 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=11.118625
I20260812 06:19:46.208009 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.035s	user 0.022s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15778,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:46.208889 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=2.188937
I20260812 06:19:46.236991 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.026s	user 0.006s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5074,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:46.237495 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=2.188937
I20260812 06:19:46.251750 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5519,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.252246 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushMRSOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=1.000000
I20260812 06:19:46.295022 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushMRSOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.043s	user 0.027s	sys 0.013s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":238,"dirs.run_wall_time_us":1493,"drs_written":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1588,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:46.295826 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling LogGCOp(00f76ba3fdfb42e68b2a22baf2c97727): free 133024367 bytes of WAL
I20260812 06:19:46.296072 31944 log_reader.cc:385] T 00f76ba3fdfb42e68b2a22baf2c97727: removed 13 log segments from log reader
I20260812 06:19:46.296134 31944 log.cc:1079] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/00f76ba3fdfb42e68b2a22baf2c97727/wal-000000014 (ops 66-70)
I20260812 06:19:46.296187 31944 log.cc:1079] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/00f76ba3fdfb42e68b2a22baf2c97727/wal-000000015 (ops 71-75)
I20260812 06:19:46.296247 31944 log.cc:1079] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/00f76ba3fdfb42e68b2a22baf2c97727/wal-000000016 (ops 76-80)
I20260812 06:19:46.296290 31944 log.cc:1079] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/00f76ba3fdfb42e68b2a22baf2c97727/wal-000000017 (ops 81-85)
I20260812 06:19:46.296329 31944 log.cc:1079] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/00f76ba3fdfb42e68b2a22baf2c97727/wal-000000018 (ops 86-90)
I20260812 06:19:46.296368 31944 log.cc:1079] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/00f76ba3fdfb42e68b2a22baf2c97727/wal-000000019 (ops 91-95)
I20260812 06:19:46.296408 31944 log.cc:1079] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/00f76ba3fdfb42e68b2a22baf2c97727/wal-000000020 (ops 96-100)
I20260812 06:19:46.296446 31944 log.cc:1079] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/00f76ba3fdfb42e68b2a22baf2c97727/wal-000000021 (ops 101-104)
I20260812 06:19:46.296484 31944 log.cc:1079] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/00f76ba3fdfb42e68b2a22baf2c97727/wal-000000022 (ops 105-109)
I20260812 06:19:46.296523 31944 log.cc:1079] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/00f76ba3fdfb42e68b2a22baf2c97727/wal-000000023 (ops 110-114)
I20260812 06:19:46.296561 31944 log.cc:1079] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/00f76ba3fdfb42e68b2a22baf2c97727/wal-000000024 (ops 115-119)
I20260812 06:19:46.296599 31944 log.cc:1079] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/00f76ba3fdfb42e68b2a22baf2c97727/wal-000000025 (ops 120-124)
I20260812 06:19:46.296640 31944 log.cc:1079] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/00f76ba3fdfb42e68b2a22baf2c97727/wal-000000026 (ops 125-129)
I20260812 06:19:46.325650 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: LogGCOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.030s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:19:46.326063 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=2.188937
I20260812 06:19:46.343199 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.017s	user 0.006s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5328,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.343791 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling UndoDeltaBlockGCOp(00f76ba3fdfb42e68b2a22baf2c97727): 483 bytes on disk
I20260812 06:19:46.344321 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: UndoDeltaBlockGCOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4}
I20260812 06:19:46.345026 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling MajorDeltaCompactionOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=1.000000
I20260812 06:19:46.563012 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: MajorDeltaCompactionOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.218s	user 0.122s	sys 0.089s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877330,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":239,"lbm_read_time_us":16137,"lbm_reads_lt_1ms":666,"lbm_write_time_us":36285,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5760,"thread_start_us":77,"threads_started":1,"update_count":3000}
I20260812 06:19:46.564015 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=18.063937
I20260812 06:19:46.631039 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.067s	user 0.030s	sys 0.035s Metrics: {"bytes_written":20512319,"delete_count":0,"lbm_write_time_us":25499,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:46.631568 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=2.188937
I20260812 06:19:46.642808 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4076,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.643460 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling MajorDeltaCompactionOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=1.000000
I20260812 06:19:46.834481 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: MajorDeltaCompactionOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.191s	user 0.143s	sys 0.048s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877105,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":925,"lbm_read_time_us":15278,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34121,"lbm_writes_lt_1ms":643,"mutex_wait_us":283,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6272,"update_count":3000}
I20260812 06:19:46.835251 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=14.095187
I20260812 06:19:46.900907 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.065s	user 0.032s	sys 0.019s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22322,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:46.901502 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=2.188937
I20260812 06:19:46.921276 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.020s	user 0.011s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":7932,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.922011 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling MajorDeltaCompactionOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=1.000000
I20260812 06:19:47.092499 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: MajorDeltaCompactionOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.170s	user 0.118s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":521,"lbm_read_time_us":13237,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27636,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":27392,"update_count":2500}
I20260812 06:19:47.093181 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=14.095187
I20260812 06:19:47.150539 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.057s	user 0.025s	sys 0.030s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":19940,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:47.151091 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=2.188937
I20260812 06:19:47.162140 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4385,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:47.162581 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling MajorDeltaCompactionOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=1.000000
I20260812 06:19:47.340705 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: MajorDeltaCompactionOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.178s	user 0.122s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1095,"lbm_read_time_us":12627,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28117,"lbm_writes_lt_1ms":543,"mutex_wait_us":341,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:19:47.341334 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=14.095187
I20260812 06:19:47.410774 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.069s	user 0.037s	sys 0.023s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":21173,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:47.411403 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=2.188937
I20260812 06:19:47.429123 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.017s	user 0.005s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6624,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:47.429708 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling MajorDeltaCompactionOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=1.000000
I20260812 06:19:47.602231 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: MajorDeltaCompactionOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.172s	user 0.118s	sys 0.054s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":796,"lbm_read_time_us":12364,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28884,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13824,"update_count":2500}
I20260812 06:19:47.602831 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=10.126437
I20260812 06:19:47.645089 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.042s	user 0.027s	sys 0.010s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16070,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:47.645763 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=2.188937
I20260812 06:19:47.657158 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.011s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4286,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:47.657896 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling MajorDeltaCompactionOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=1.000000
I20260812 06:19:47.796236 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: MajorDeltaCompactionOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.138s	user 0.102s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":247,"lbm_read_time_us":8325,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25225,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2000}
I20260812 06:19:47.796928 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=11.118625
I20260812 06:19:47.836747 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.040s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17979,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:47.837739 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=2.188937
I20260812 06:19:47.867813 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.030s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5836,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:47.868361 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=2.188937
I20260812 06:19:47.885082 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.016s	user 0.005s	sys 0.011s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6501,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:47.885691 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushMRSOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=1.000000
I20260812 06:19:47.918980 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushMRSOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.033s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":234,"dirs.run_wall_time_us":1468,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1919,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:47.919752 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling LogGCOp(00f76ba3fdfb42e68b2a22baf2c97727): free 133024646 bytes of WAL
I20260812 06:19:47.920030 31944 log_reader.cc:385] T 00f76ba3fdfb42e68b2a22baf2c97727: removed 13 log segments from log reader
I20260812 06:19:47.920081 31944 log.cc:1079] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/00f76ba3fdfb42e68b2a22baf2c97727/wal-000000027 (ops 130-134)
I20260812 06:19:47.920115 31944 log.cc:1079] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/00f76ba3fdfb42e68b2a22baf2c97727/wal-000000028 (ops 135-139)
I20260812 06:19:47.920185 31944 log.cc:1079] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/00f76ba3fdfb42e68b2a22baf2c97727/wal-000000029 (ops 140-144)
I20260812 06:19:47.920224 31944 log.cc:1079] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/00f76ba3fdfb42e68b2a22baf2c97727/wal-000000030 (ops 145-149)
I20260812 06:19:47.920286 31944 log.cc:1079] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/00f76ba3fdfb42e68b2a22baf2c97727/wal-000000031 (ops 150-154)
I20260812 06:19:47.920337 31944 log.cc:1079] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/00f76ba3fdfb42e68b2a22baf2c97727/wal-000000032 (ops 155-159)
I20260812 06:19:47.920425 31944 log.cc:1079] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/00f76ba3fdfb42e68b2a22baf2c97727/wal-000000033 (ops 160-164)
I20260812 06:19:47.920459 31944 log.cc:1079] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/00f76ba3fdfb42e68b2a22baf2c97727/wal-000000034 (ops 165-169)
I20260812 06:19:47.920506 31944 log.cc:1079] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/00f76ba3fdfb42e68b2a22baf2c97727/wal-000000035 (ops 170-174)
I20260812 06:19:47.920552 31944 log.cc:1079] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/00f76ba3fdfb42e68b2a22baf2c97727/wal-000000036 (ops 175-179)
I20260812 06:19:47.920595 31944 log.cc:1079] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/00f76ba3fdfb42e68b2a22baf2c97727/wal-000000037 (ops 180-184)
I20260812 06:19:47.920639 31944 log.cc:1079] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/00f76ba3fdfb42e68b2a22baf2c97727/wal-000000038 (ops 185-188)
I20260812 06:19:47.920696 31944 log.cc:1079] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/00f76ba3fdfb42e68b2a22baf2c97727/wal-000000039 (ops 189-193)
I20260812 06:19:47.953380 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: LogGCOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.033s	user 0.002s	sys 0.031s Metrics: {}
I20260812 06:19:47.953874 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling UndoDeltaBlockGCOp(00f76ba3fdfb42e68b2a22baf2c97727): 481 bytes on disk
I20260812 06:19:47.954345 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: UndoDeltaBlockGCOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:19:47.954926 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=5.165500
I20260812 06:19:47.980650 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.026s	user 0.018s	sys 0.003s Metrics: {"bytes_written":7056402,"delete_count":0,"lbm_write_time_us":10379,"lbm_writes_lt_1ms":175,"reinsert_count":0,"update_count":860}
I20260812 06:19:47.981317 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=1.000000
I20260812 06:19:47.988283 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.007s	user 0.001s	sys 0.004s Metrics: {"bytes_written":1148852,"delete_count":0,"lbm_write_time_us":2084,"lbm_writes_lt_1ms":31,"reinsert_count":0,"update_count":140}
I20260812 06:19:47.988745 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling MajorDeltaCompactionOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=1.000000
I20260812 06:19:48.133112 31750 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.020s	user 1.884s	sys 0.135s
I20260812 06:19:48.230830 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: MajorDeltaCompactionOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.242s	user 0.150s	sys 0.084s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979791,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":869,"lbm_read_time_us":15694,"lbm_reads_lt_1ms":771,"lbm_write_time_us":40855,"lbm_writes_lt_1ms":743,"mutex_wait_us":273,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":9216,"thread_start_us":104,"threads_started":1,"update_count":3500}
I20260812 06:19:48.231562 32059 maintenance_manager.cc:419] P 562bb2f18ea2421b868ebb81c9ad8dd6: Scheduling FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727): perf score=10.126437
I20260812 06:19:48.237524 31750 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.104s	user 0.003s	sys 0.000s
I20260812 06:19:48.238135 31750 tablet_server.cc:179] TabletServer@127.31.1.129:0 shutting down...
I20260812 06:19:48.268307 31944 maintenance_manager.cc:643] P 562bb2f18ea2421b868ebb81c9ad8dd6: FlushDeltaMemStoresOp(00f76ba3fdfb42e68b2a22baf2c97727) complete. Timing: real 0.037s	user 0.022s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15898,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:48.269057 31750 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:48.269513 31750 tablet_replica.cc:333] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6: stopping tablet replica
I20260812 06:19:48.269797 31750 raft_consensus.cc:2243] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:48.270051 31750 raft_consensus.cc:2272] T 00f76ba3fdfb42e68b2a22baf2c97727 P 562bb2f18ea2421b868ebb81c9ad8dd6 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:48.290869 31750 tablet_server.cc:196] TabletServer@127.31.1.129:0 shutdown complete.
I20260812 06:19:48.295405 31750 master.cc:562] Master@127.31.1.190:39251 shutting down...
I20260812 06:19:48.299400 31750 raft_consensus.cc:2243] T 00000000000000000000000000000000 P ae896aa257e9472f82373c886d7a0826 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:48.299580 31750 raft_consensus.cc:2272] T 00000000000000000000000000000000 P ae896aa257e9472f82373c886d7a0826 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:48.299675 31750 tablet_replica.cc:333] T 00000000000000000000000000000000 P ae896aa257e9472f82373c886d7a0826: stopping tablet replica
I20260812 06:19:48.312103 31750 master.cc:584] Master@127.31.1.190:39251 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5572 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:48.415599 31750 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.31.1.190:37219
I20260812 06:19:48.416045 31750 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:48.418217 32124 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:48.418258 31750 server_base.cc:1061] running on GCE node
W20260812 06:19:48.418476 32126 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:48.418509 32123 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:48.418716 31750 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:48.418788 31750 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:48.418805 31750 hybrid_clock.cc:648] HybridClock initialized: now 1786515588418805 us; error 0 us; skew 500 ppm
I20260812 06:19:48.419605 31750 webserver.cc:533] Webserver started at http://127.31.1.190:32865/ using document root <none> and password file <none>
I20260812 06:19:48.419809 31750 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:48.419854 31750 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:48.419909 31750 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:48.420262 31750 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/master-0-root/instance:
uuid: "6038ec2f89c44ff5863cba22512aa78f"
format_stamp: "Formatted at 2026-08-12 06:19:48 on dist-test-slave-g170"
I20260812 06:19:48.421861 31750 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:48.422758 32134 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:48.423002 31750 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:48.423091 31750 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/master-0-root
uuid: "6038ec2f89c44ff5863cba22512aa78f"
format_stamp: "Formatted at 2026-08-12 06:19:48 on dist-test-slave-g170"
I20260812 06:19:48.423177 31750 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:48.430166 31750 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:48.430485 31750 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:48.434599 31750 rpc_server.cc:307] RPC server started. Bound to: 127.31.1.190:37219
I20260812 06:19:48.437908 32227 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.31.1.190:37219 every 8 connection(s)
I20260812 06:19:48.438084 32231 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:48.441885 32231 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6038ec2f89c44ff5863cba22512aa78f: Bootstrap starting.
I20260812 06:19:48.442711 32231 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 6038ec2f89c44ff5863cba22512aa78f: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:48.443735 32231 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6038ec2f89c44ff5863cba22512aa78f: No bootstrap required, opened a new log
I20260812 06:19:48.444154 32231 raft_consensus.cc:359] T 00000000000000000000000000000000 P 6038ec2f89c44ff5863cba22512aa78f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6038ec2f89c44ff5863cba22512aa78f" member_type: VOTER }
I20260812 06:19:48.444239 32231 raft_consensus.cc:385] T 00000000000000000000000000000000 P 6038ec2f89c44ff5863cba22512aa78f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:48.444295 32231 raft_consensus.cc:740] T 00000000000000000000000000000000 P 6038ec2f89c44ff5863cba22512aa78f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6038ec2f89c44ff5863cba22512aa78f, State: Initialized, Role: FOLLOWER
I20260812 06:19:48.444476 32231 consensus_queue.cc:260] T 00000000000000000000000000000000 P 6038ec2f89c44ff5863cba22512aa78f [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: "6038ec2f89c44ff5863cba22512aa78f" member_type: VOTER }
I20260812 06:19:48.444547 32231 raft_consensus.cc:399] T 00000000000000000000000000000000 P 6038ec2f89c44ff5863cba22512aa78f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:48.444604 32231 raft_consensus.cc:493] T 00000000000000000000000000000000 P 6038ec2f89c44ff5863cba22512aa78f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:48.444671 32231 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 6038ec2f89c44ff5863cba22512aa78f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:48.445359 32231 raft_consensus.cc:515] T 00000000000000000000000000000000 P 6038ec2f89c44ff5863cba22512aa78f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6038ec2f89c44ff5863cba22512aa78f" member_type: VOTER }
I20260812 06:19:48.445498 32231 leader_election.cc:304] T 00000000000000000000000000000000 P 6038ec2f89c44ff5863cba22512aa78f [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: 6038ec2f89c44ff5863cba22512aa78f; no voters: 
I20260812 06:19:48.445712 32231 leader_election.cc:290] T 00000000000000000000000000000000 P 6038ec2f89c44ff5863cba22512aa78f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:48.445858 32235 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 6038ec2f89c44ff5863cba22512aa78f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:48.446060 32235 raft_consensus.cc:697] T 00000000000000000000000000000000 P 6038ec2f89c44ff5863cba22512aa78f [term 1 LEADER]: Becoming Leader. State: Replica: 6038ec2f89c44ff5863cba22512aa78f, State: Running, Role: LEADER
I20260812 06:19:48.446139 32231 sys_catalog.cc:565] T 00000000000000000000000000000000 P 6038ec2f89c44ff5863cba22512aa78f [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:48.446213 32235 consensus_queue.cc:237] T 00000000000000000000000000000000 P 6038ec2f89c44ff5863cba22512aa78f [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: "6038ec2f89c44ff5863cba22512aa78f" member_type: VOTER }
I20260812 06:19:48.446702 32239 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6038ec2f89c44ff5863cba22512aa78f [sys.catalog]: SysCatalogTable state changed. Reason: New leader 6038ec2f89c44ff5863cba22512aa78f. Latest consensus state: current_term: 1 leader_uuid: "6038ec2f89c44ff5863cba22512aa78f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6038ec2f89c44ff5863cba22512aa78f" member_type: VOTER } }
I20260812 06:19:48.446686 32236 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6038ec2f89c44ff5863cba22512aa78f [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "6038ec2f89c44ff5863cba22512aa78f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6038ec2f89c44ff5863cba22512aa78f" member_type: VOTER } }
I20260812 06:19:48.446801 32239 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6038ec2f89c44ff5863cba22512aa78f [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:48.446810 32236 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6038ec2f89c44ff5863cba22512aa78f [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:48.447074 32247 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:48.447921 32247 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:48.448094 31750 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:48.449767 32247 catalog_manager.cc:1383] Generated new cluster ID: b3e5bee9a4fd4e769a714b9c092f7ed2
I20260812 06:19:48.449826 32247 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:48.485071 32247 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:48.485674 32247 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:48.491282 32247 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 6038ec2f89c44ff5863cba22512aa78f: Generated new TSK 0
I20260812 06:19:48.491489 32247 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:48.512749 31750 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:48.514950 32272 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:48.515021 32274 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:48.515205 31750 server_base.cc:1061] running on GCE node
W20260812 06:19:48.514981 32270 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:48.515458 31750 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:48.515527 31750 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:48.515563 31750 hybrid_clock.cc:648] HybridClock initialized: now 1786515588515561 us; error 0 us; skew 500 ppm
I20260812 06:19:48.516464 31750 webserver.cc:533] Webserver started at http://127.31.1.129:43825/ using document root <none> and password file <none>
I20260812 06:19:48.516695 31750 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:48.516798 31750 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:48.516917 31750 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:48.517320 31750 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root/instance:
uuid: "a7c90e037d3343caa416e8e17f24ff94"
format_stamp: "Formatted at 2026-08-12 06:19:48 on dist-test-slave-g170"
I20260812 06:19:48.518841 31750 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:48.519855 32279 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:48.520124 31750 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:48.520215 31750 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root
uuid: "a7c90e037d3343caa416e8e17f24ff94"
format_stamp: "Formatted at 2026-08-12 06:19:48 on dist-test-slave-g170"
I20260812 06:19:48.520299 31750 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:48.539400 31750 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:48.539814 31750 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:48.540131 31750 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:48.540608 31750 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:48.540680 31750 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:48.540742 31750 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:48.540843 31750 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:48.545167 31750 rpc_server.cc:307] RPC server started. Bound to: 127.31.1.129:39671
I20260812 06:19:48.545606 32409 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.31.1.129:39671 every 8 connection(s)
I20260812 06:19:48.555598 32410 heartbeater.cc:344] Connected to a master server at 127.31.1.190:37219
I20260812 06:19:48.555740 32410 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:48.556007 32410 heartbeater.cc:507] Master 127.31.1.190:37219 requested a full tablet report, sending...
I20260812 06:19:48.556914 32164 ts_manager.cc:194] Registered new tserver with Master: a7c90e037d3343caa416e8e17f24ff94 (127.31.1.129:39671)
I20260812 06:19:48.557014 31750 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011211023s
I20260812 06:19:48.557811 32164 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:49392
I20260812 06:19:48.564558 32164 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:49406:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:48.573698 32331 tablet_service.cc:1511] Processing CreateTablet for tablet b61b0679b25e409d93dce3c2bf1d98ff (DEFAULT_TABLE table=heavy-update-compaction-test [id=327a160d72f14aa194a9774b02a71bc6]), partition=
I20260812 06:19:48.573940 32331 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet b61b0679b25e409d93dce3c2bf1d98ff. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:48.575901 32427 tablet_bootstrap.cc:492] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Bootstrap starting.
I20260812 06:19:48.577068 32427 tablet_bootstrap.cc:654] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:48.578274 32427 tablet_bootstrap.cc:492] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: No bootstrap required, opened a new log
I20260812 06:19:48.578393 32427 ts_tablet_manager.cc:1403] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:48.578866 32427 raft_consensus.cc:359] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a7c90e037d3343caa416e8e17f24ff94" member_type: VOTER last_known_addr { host: "127.31.1.129" port: 39671 } }
I20260812 06:19:48.578966 32427 raft_consensus.cc:385] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:48.579025 32427 raft_consensus.cc:740] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a7c90e037d3343caa416e8e17f24ff94, State: Initialized, Role: FOLLOWER
I20260812 06:19:48.579217 32427 consensus_queue.cc:260] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94 [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: "a7c90e037d3343caa416e8e17f24ff94" member_type: VOTER last_known_addr { host: "127.31.1.129" port: 39671 } }
I20260812 06:19:48.579303 32427 raft_consensus.cc:399] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:48.579371 32427 raft_consensus.cc:493] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:48.579432 32427 raft_consensus.cc:3060] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:48.580379 32427 raft_consensus.cc:515] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a7c90e037d3343caa416e8e17f24ff94" member_type: VOTER last_known_addr { host: "127.31.1.129" port: 39671 } }
I20260812 06:19:48.580538 32427 leader_election.cc:304] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94 [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: a7c90e037d3343caa416e8e17f24ff94; no voters: 
I20260812 06:19:48.580799 32427 leader_election.cc:290] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:48.580974 32433 raft_consensus.cc:2804] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:48.581215 32433 raft_consensus.cc:697] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94 [term 1 LEADER]: Becoming Leader. State: Replica: a7c90e037d3343caa416e8e17f24ff94, State: Running, Role: LEADER
I20260812 06:19:48.581238 32427 ts_tablet_manager.cc:1434] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:48.581295 32410 heartbeater.cc:499] Master 127.31.1.190:37219 was elected leader, sending a full tablet report...
I20260812 06:19:48.581375 32433 consensus_queue.cc:237] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94 [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: "a7c90e037d3343caa416e8e17f24ff94" member_type: VOTER last_known_addr { host: "127.31.1.129" port: 39671 } }
I20260812 06:19:48.582773 32164 catalog_manager.cc:5719] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94 reported cstate change: term changed from 0 to 1, leader changed from <none> to a7c90e037d3343caa416e8e17f24ff94 (127.31.1.129). New cstate: current_term: 1 leader_uuid: "a7c90e037d3343caa416e8e17f24ff94" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a7c90e037d3343caa416e8e17f24ff94" member_type: VOTER last_known_addr { host: "127.31.1.129" port: 39671 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:48.644203 31750 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.009s	sys 0.014s
I20260812 06:19:48.796722 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushMRSOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=19.054940
I20260812 06:19:48.955307 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushMRSOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.158s	user 0.124s	sys 0.032s Metrics: {"bytes_written":12717737,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":79,"dirs.run_cpu_time_us":313,"dirs.run_wall_time_us":930,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":37187,"lbm_writes_lt_1ms":767,"mutex_wait_us":212,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":6912,"update_count":1550}
I20260812 06:19:48.956182 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling LogGCOp(b61b0679b25e409d93dce3c2bf1d98ff): free 20743880 bytes of WAL
I20260812 06:19:48.956450 32290 log_reader.cc:385] T b61b0679b25e409d93dce3c2bf1d98ff: removed 2 log segments from log reader
I20260812 06:19:48.956499 32290 log.cc:1079] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/b61b0679b25e409d93dce3c2bf1d98ff/wal-000000001 (ops 1-6)
I20260812 06:19:48.956532 32290 log.cc:1079] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/b61b0679b25e409d93dce3c2bf1d98ff/wal-000000002 (ops 7-11)
I20260812 06:19:48.961055 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: LogGCOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.005s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:19:48.961405 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=2.188937
I20260812 06:19:48.975663 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.014s	user 0.009s	sys 0.002s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5061,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:48.976152 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling MajorDeltaCompactionOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=1.000000
I20260812 06:19:49.134187 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: MajorDeltaCompactionOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.158s	user 0.110s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672270,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":545,"lbm_read_time_us":10313,"lbm_reads_lt_1ms":464,"lbm_write_time_us":29306,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":352,"threads_started":5,"update_count":2000}
I20260812 06:19:49.134784 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=10.126437
I20260812 06:19:49.185074 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.050s	user 0.030s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16887,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:49.185527 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling UndoDeltaBlockGCOp(b61b0679b25e409d93dce3c2bf1d98ff): 16411392 bytes on disk
I20260812 06:19:49.185952 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: UndoDeltaBlockGCOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:19:49.186348 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=2.188937
I20260812 06:19:49.197088 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4159,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.197492 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling MajorDeltaCompactionOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=1.000000
I20260812 06:19:49.355126 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: MajorDeltaCompactionOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.157s	user 0.109s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":260,"lbm_read_time_us":11705,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25996,"lbm_writes_lt_1ms":443,"mutex_wait_us":52,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2000}
I20260812 06:19:49.355991 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=10.126437
I20260812 06:19:49.393508 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.037s	user 0.021s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14529,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:49.393965 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=2.188937
I20260812 06:19:49.408524 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5666,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.409188 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling MajorDeltaCompactionOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=1.000000
I20260812 06:19:49.545773 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: MajorDeltaCompactionOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.136s	user 0.099s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":97,"lbm_read_time_us":9219,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24740,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2000}
I20260812 06:19:49.546460 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=10.126437
I20260812 06:19:49.588177 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.041s	user 0.024s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17006,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:49.588909 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=2.188937
I20260812 06:19:49.601263 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.012s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4493,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.601725 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling MajorDeltaCompactionOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=1.000000
I20260812 06:19:49.744674 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: MajorDeltaCompactionOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.143s	user 0.102s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":240,"lbm_read_time_us":10802,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27455,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2000}
I20260812 06:19:49.745340 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=10.126437
I20260812 06:19:49.791484 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.046s	user 0.021s	sys 0.022s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15924,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:49.792101 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=2.188937
I20260812 06:19:49.803514 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4602,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.804009 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling MajorDeltaCompactionOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=1.000000
I20260812 06:19:49.961974 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: MajorDeltaCompactionOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.158s	user 0.110s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1006,"lbm_read_time_us":11847,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26674,"lbm_writes_lt_1ms":443,"mutex_wait_us":90,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14080,"update_count":2000}
I20260812 06:19:49.962599 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=10.126437
I20260812 06:19:50.009260 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.046s	user 0.016s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14312,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:50.009759 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=2.188937
I20260812 06:19:50.021417 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.011s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4410,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:50.022385 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling MajorDeltaCompactionOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=1.000000
I20260812 06:19:50.161208 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: MajorDeltaCompactionOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.139s	user 0.103s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":414,"lbm_read_time_us":11792,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27551,"lbm_writes_lt_1ms":443,"mutex_wait_us":84,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13568,"update_count":2000}
I20260812 06:19:50.161801 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=10.126437
I20260812 06:19:50.204712 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.043s	user 0.021s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17879,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:50.205215 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=2.188937
I20260812 06:19:50.215706 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4132,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:50.216460 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushMRSOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=1.000000
I20260812 06:19:50.244656 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushMRSOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.028s	user 0.023s	sys 0.004s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":258,"dirs.run_wall_time_us":1321,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1469,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:50.245322 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling LogGCOp(b61b0679b25e409d93dce3c2bf1d98ff): free 112239259 bytes of WAL
I20260812 06:19:50.245546 32290 log_reader.cc:385] T b61b0679b25e409d93dce3c2bf1d98ff: removed 11 log segments from log reader
I20260812 06:19:50.245590 32290 log.cc:1079] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/b61b0679b25e409d93dce3c2bf1d98ff/wal-000000003 (ops 12-16)
I20260812 06:19:50.245618 32290 log.cc:1079] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/b61b0679b25e409d93dce3c2bf1d98ff/wal-000000004 (ops 17-21)
I20260812 06:19:50.245680 32290 log.cc:1079] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/b61b0679b25e409d93dce3c2bf1d98ff/wal-000000005 (ops 22-26)
I20260812 06:19:50.245721 32290 log.cc:1079] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/b61b0679b25e409d93dce3c2bf1d98ff/wal-000000006 (ops 27-31)
I20260812 06:19:50.245762 32290 log.cc:1079] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/b61b0679b25e409d93dce3c2bf1d98ff/wal-000000007 (ops 32-36)
I20260812 06:19:50.245810 32290 log.cc:1079] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/b61b0679b25e409d93dce3c2bf1d98ff/wal-000000008 (ops 37-41)
I20260812 06:19:50.245846 32290 log.cc:1079] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/b61b0679b25e409d93dce3c2bf1d98ff/wal-000000009 (ops 42-46)
I20260812 06:19:50.245883 32290 log.cc:1079] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/b61b0679b25e409d93dce3c2bf1d98ff/wal-000000010 (ops 47-50)
I20260812 06:19:50.245922 32290 log.cc:1079] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/b61b0679b25e409d93dce3c2bf1d98ff/wal-000000011 (ops 51-55)
I20260812 06:19:50.245960 32290 log.cc:1079] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/b61b0679b25e409d93dce3c2bf1d98ff/wal-000000012 (ops 56-60)
I20260812 06:19:50.245999 32290 log.cc:1079] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/b61b0679b25e409d93dce3c2bf1d98ff/wal-000000013 (ops 61-65)
I20260812 06:19:50.273857 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: LogGCOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.028s	user 0.003s	sys 0.024s Metrics: {}
I20260812 06:19:50.274557 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling UndoDeltaBlockGCOp(b61b0679b25e409d93dce3c2bf1d98ff): 448 bytes on disk
I20260812 06:19:50.275182 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: UndoDeltaBlockGCOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:19:50.275628 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=3.181125
I20260812 06:19:50.288388 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.013s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":4447,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:50.289007 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=2.188937
I20260812 06:19:50.298451 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3687,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:50.298866 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling MajorDeltaCompactionOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=1.000000
I20260812 06:19:50.487177 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: MajorDeltaCompactionOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.188s	user 0.139s	sys 0.044s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877323,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":265,"lbm_read_time_us":12713,"lbm_reads_lt_1ms":674,"lbm_write_time_us":39655,"lbm_writes_lt_1ms":643,"mutex_wait_us":24,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":15104,"thread_start_us":104,"threads_started":1,"update_count":3000}
I20260812 06:19:50.487900 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=14.095187
I20260812 06:19:50.542979 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.055s	user 0.021s	sys 0.031s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":26501,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:50.543450 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=2.188937
I20260812 06:19:50.559893 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6400,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:50.560491 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling MajorDeltaCompactionOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=1.000000
I20260812 06:19:50.714180 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: MajorDeltaCompactionOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.154s	user 0.109s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":284,"lbm_read_time_us":11924,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29501,"lbm_writes_lt_1ms":543,"mutex_wait_us":49,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18688,"update_count":2500}
I20260812 06:19:50.714887 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=12.110812
I20260812 06:19:50.760022 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.045s	user 0.016s	sys 0.025s Metrics: {"bytes_written":14399714,"delete_count":0,"lbm_write_time_us":19697,"lbm_writes_lt_1ms":354,"reinsert_count":0,"update_count":1755}
I20260812 06:19:50.760521 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=1.196750
I20260812 06:19:50.780488 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.020s	user 0.007s	sys 0.000s Metrics: {"bytes_written":2420633,"delete_count":0,"lbm_write_time_us":2978,"lbm_writes_lt_1ms":62,"reinsert_count":0,"update_count":295}
I20260812 06:19:50.781041 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=2.188937
I20260812 06:19:50.790417 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.009s	user 0.003s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3641,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:50.790863 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling MajorDeltaCompactionOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=1.000000
I20260812 06:19:50.959708 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: MajorDeltaCompactionOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.169s	user 0.108s	sys 0.061s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774752,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":993,"lbm_read_time_us":12643,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29896,"lbm_writes_lt_1ms":543,"mutex_wait_us":356,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":38784,"update_count":2500}
I20260812 06:19:50.960397 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=14.095187
I20260812 06:19:51.015666 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.055s	user 0.024s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21169,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:51.016177 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=2.188937
I20260812 06:19:51.027102 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4269,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.027731 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling MajorDeltaCompactionOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=1.000000
I20260812 06:19:51.190671 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: MajorDeltaCompactionOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.163s	user 0.112s	sys 0.050s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1016,"lbm_read_time_us":12643,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27700,"lbm_writes_lt_1ms":543,"mutex_wait_us":341,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:19:51.191190 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=14.095187
I20260812 06:19:51.256821 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.065s	user 0.033s	sys 0.032s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25963,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:19:51.257405 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=2.188937
I20260812 06:19:51.274536 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.017s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6446,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.275134 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling MajorDeltaCompactionOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=1.000000
I20260812 06:19:51.458835 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: MajorDeltaCompactionOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.183s	user 0.107s	sys 0.072s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":318,"lbm_read_time_us":13045,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29801,"lbm_writes_lt_1ms":543,"mutex_wait_us":65,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":82688,"update_count":2500}
I20260812 06:19:51.459597 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=14.095187
I20260812 06:19:51.523737 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.064s	user 0.026s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20670,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:51.524348 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=2.188937
I20260812 06:19:51.535441 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4380,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.536103 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling MajorDeltaCompactionOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=1.000000
I20260812 06:19:51.722209 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: MajorDeltaCompactionOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.186s	user 0.133s	sys 0.047s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":712,"lbm_read_time_us":13306,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29245,"lbm_writes_lt_1ms":543,"mutex_wait_us":290,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":700928,"update_count":2500}
I20260812 06:19:51.722834 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=14.095187
I20260812 06:19:51.774736 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.052s	user 0.024s	sys 0.024s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":22091,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:51.775306 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=2.188937
I20260812 06:19:51.797515 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.022s	user 0.003s	sys 0.019s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4625,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.798046 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushMRSOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=1.000000
I20260812 06:19:51.833788 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushMRSOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.036s	user 0.033s	sys 0.002s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":40,"dirs.run_cpu_time_us":266,"dirs.run_wall_time_us":1311,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1794,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:51.834549 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling LogGCOp(b61b0679b25e409d93dce3c2bf1d98ff): free 133024427 bytes of WAL
I20260812 06:19:51.834862 32290 log_reader.cc:385] T b61b0679b25e409d93dce3c2bf1d98ff: removed 13 log segments from log reader
I20260812 06:19:51.834929 32290 log.cc:1079] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/b61b0679b25e409d93dce3c2bf1d98ff/wal-000000014 (ops 66-70)
I20260812 06:19:51.834960 32290 log.cc:1079] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/b61b0679b25e409d93dce3c2bf1d98ff/wal-000000015 (ops 71-75)
I20260812 06:19:51.835028 32290 log.cc:1079] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/b61b0679b25e409d93dce3c2bf1d98ff/wal-000000016 (ops 76-80)
I20260812 06:19:51.835073 32290 log.cc:1079] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/b61b0679b25e409d93dce3c2bf1d98ff/wal-000000017 (ops 81-84)
I20260812 06:19:51.835160 32290 log.cc:1079] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/b61b0679b25e409d93dce3c2bf1d98ff/wal-000000018 (ops 85-89)
I20260812 06:19:51.835207 32290 log.cc:1079] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/b61b0679b25e409d93dce3c2bf1d98ff/wal-000000019 (ops 90-94)
I20260812 06:19:51.835244 32290 log.cc:1079] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/b61b0679b25e409d93dce3c2bf1d98ff/wal-000000020 (ops 95-99)
I20260812 06:19:51.835290 32290 log.cc:1079] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/b61b0679b25e409d93dce3c2bf1d98ff/wal-000000021 (ops 100-104)
I20260812 06:19:51.835332 32290 log.cc:1079] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/b61b0679b25e409d93dce3c2bf1d98ff/wal-000000022 (ops 105-109)
I20260812 06:19:51.835373 32290 log.cc:1079] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/b61b0679b25e409d93dce3c2bf1d98ff/wal-000000023 (ops 110-114)
I20260812 06:19:51.835412 32290 log.cc:1079] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/b61b0679b25e409d93dce3c2bf1d98ff/wal-000000024 (ops 115-119)
I20260812 06:19:51.835451 32290 log.cc:1079] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/b61b0679b25e409d93dce3c2bf1d98ff/wal-000000025 (ops 120-124)
I20260812 06:19:51.835490 32290 log.cc:1079] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/b61b0679b25e409d93dce3c2bf1d98ff/wal-000000026 (ops 125-129)
I20260812 06:19:51.867077 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: LogGCOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.032s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:19:51.867507 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling UndoDeltaBlockGCOp(b61b0679b25e409d93dce3c2bf1d98ff): 492 bytes on disk
I20260812 06:19:51.868062 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: UndoDeltaBlockGCOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:19:51.868605 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=3.181125
I20260812 06:19:51.883285 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.014s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":5482,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:51.883797 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=2.188937
I20260812 06:19:51.897404 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.013s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5209,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:51.897945 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling MajorDeltaCompactionOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=1.000000
I20260812 06:19:52.150436 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: MajorDeltaCompactionOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.252s	user 0.167s	sys 0.075s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979734,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1094,"lbm_read_time_us":16892,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40396,"lbm_writes_lt_1ms":743,"mutex_wait_us":390,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":40576,"thread_start_us":87,"threads_started":1,"update_count":3500}
I20260812 06:19:52.151234 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=18.063937
I20260812 06:19:52.219096 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.068s	user 0.034s	sys 0.020s Metrics: {"bytes_written":20512320,"delete_count":0,"lbm_write_time_us":25693,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:52.219574 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=2.188937
I20260812 06:19:52.230844 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4249,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.231771 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling MajorDeltaCompactionOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=1.000000
I20260812 06:19:52.456703 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: MajorDeltaCompactionOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.225s	user 0.155s	sys 0.069s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877107,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":177,"lbm_read_time_us":15693,"lbm_reads_lt_1ms":672,"lbm_write_time_us":39678,"lbm_writes_lt_1ms":643,"mutex_wait_us":32,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7680,"update_count":3000}
I20260812 06:19:52.457458 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=14.095187
I20260812 06:19:52.501582 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.044s	user 0.027s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19516,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:52.502211 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=2.188937
I20260812 06:19:52.518165 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.016s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5378,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.518832 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling MajorDeltaCompactionOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=1.000000
I20260812 06:19:52.691150 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: MajorDeltaCompactionOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.172s	user 0.119s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":288,"lbm_read_time_us":12490,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28936,"lbm_writes_lt_1ms":543,"mutex_wait_us":78,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2500}
I20260812 06:19:52.691627 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=15.087375
I20260812 06:19:52.764565 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.073s	user 0.025s	sys 0.039s Metrics: {"bytes_written":16820145,"delete_count":0,"lbm_write_time_us":29627,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:52.765162 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=2.188937
I20260812 06:19:52.791308 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.018s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4553926,"delete_count":0,"lbm_write_time_us":7655,"lbm_writes_lt_1ms":114,"reinsert_count":0,"update_count":555}
I20260812 06:19:52.791783 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=2.188937
I20260812 06:19:52.801710 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3241130,"delete_count":0,"lbm_write_time_us":3710,"lbm_writes_lt_1ms":82,"reinsert_count":0,"update_count":395}
I20260812 06:19:52.802241 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling MajorDeltaCompactionOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=1.000000
I20260812 06:19:53.007632 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: MajorDeltaCompactionOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.205s	user 0.145s	sys 0.060s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877201,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":165,"lbm_read_time_us":13966,"lbm_reads_lt_1ms":673,"lbm_write_time_us":36396,"lbm_writes_lt_1ms":643,"mutex_wait_us":51,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13696,"update_count":3000}
I20260812 06:19:53.008442 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=14.095187
I20260812 06:19:53.059862 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.051s	user 0.028s	sys 0.020s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":22758,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:53.060392 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=2.188937
I20260812 06:19:53.073076 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4872,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:53.073526 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling MajorDeltaCompactionOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=1.000000
I20260812 06:19:53.240602 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: MajorDeltaCompactionOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.167s	user 0.107s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":276,"lbm_read_time_us":11123,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27209,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8576,"update_count":2500}
I20260812 06:19:53.241248 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=14.095187
I20260812 06:19:53.299365 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.058s	user 0.039s	sys 0.004s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19354,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:53.299974 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=2.188937
I20260812 06:19:53.312471 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4621,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:53.313210 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushMRSOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=1.000000
I20260812 06:19:53.348073 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushMRSOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.035s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":184,"dirs.run_wall_time_us":1361,"drs_written":1,"lbm_read_time_us":140,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1432,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29,"spinlock_wait_cycles":1408}
I20260812 06:19:53.348893 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling LogGCOp(b61b0679b25e409d93dce3c2bf1d98ff): free 116849781 bytes of WAL
I20260812 06:19:53.349153 32290 log_reader.cc:385] T b61b0679b25e409d93dce3c2bf1d98ff: removed 12 log segments from log reader
I20260812 06:19:53.349237 32290 log.cc:1079] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/b61b0679b25e409d93dce3c2bf1d98ff/wal-000000027 (ops 130-134)
I20260812 06:19:53.349298 32290 log.cc:1079] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/b61b0679b25e409d93dce3c2bf1d98ff/wal-000000028 (ops 135-138)
I20260812 06:19:53.349339 32290 log.cc:1079] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/b61b0679b25e409d93dce3c2bf1d98ff/wal-000000029 (ops 139-143)
I20260812 06:19:53.349383 32290 log.cc:1079] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/b61b0679b25e409d93dce3c2bf1d98ff/wal-000000030 (ops 144-148)
I20260812 06:19:53.349427 32290 log.cc:1079] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/b61b0679b25e409d93dce3c2bf1d98ff/wal-000000031 (ops 149-152)
I20260812 06:19:53.349471 32290 log.cc:1079] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/b61b0679b25e409d93dce3c2bf1d98ff/wal-000000032 (ops 153-157)
I20260812 06:19:53.349514 32290 log.cc:1079] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/b61b0679b25e409d93dce3c2bf1d98ff/wal-000000033 (ops 158-162)
I20260812 06:19:53.349560 32290 log.cc:1079] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/b61b0679b25e409d93dce3c2bf1d98ff/wal-000000034 (ops 163-166)
I20260812 06:19:53.349601 32290 log.cc:1079] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/b61b0679b25e409d93dce3c2bf1d98ff/wal-000000035 (ops 167-171)
I20260812 06:19:53.349644 32290 log.cc:1079] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/b61b0679b25e409d93dce3c2bf1d98ff/wal-000000036 (ops 172-176)
I20260812 06:19:53.349685 32290 log.cc:1079] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/b61b0679b25e409d93dce3c2bf1d98ff/wal-000000037 (ops 177-181)
I20260812 06:19:53.349731 32290 log.cc:1079] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: Deleting log segment in path: /tmp/dist-test-task5SzT5Y/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515582820471-31750-0/minicluster-data/ts-0-root/wals/b61b0679b25e409d93dce3c2bf1d98ff/wal-000000038 (ops 182-186)
I20260812 06:19:53.380075 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: LogGCOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.031s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:19:53.380573 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling UndoDeltaBlockGCOp(b61b0679b25e409d93dce3c2bf1d98ff): 463 bytes on disk
I20260812 06:19:53.381165 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: UndoDeltaBlockGCOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4}
I20260812 06:19:53.381773 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=3.181125
I20260812 06:19:53.404857 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.023s	user 0.005s	sys 0.015s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":8276,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:53.405462 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=2.188937
I20260812 06:19:53.416275 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.011s	user 0.000s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4217,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:53.417014 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling MajorDeltaCompactionOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=1.000000
I20260812 06:19:53.651379 31750 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.007s	user 1.863s	sys 0.179s
I20260812 06:19:53.657019 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: MajorDeltaCompactionOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.240s	user 0.152s	sys 0.073s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979739,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2872,"lbm_read_time_us":16763,"lbm_reads_lt_1ms":774,"lbm_write_time_us":42435,"lbm_writes_lt_1ms":743,"mutex_wait_us":41,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":770048,"thread_start_us":88,"threads_started":1,"update_count":3500}
I20260812 06:19:53.657694 32411 maintenance_manager.cc:419] P a7c90e037d3343caa416e8e17f24ff94: Scheduling FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff): perf score=18.063937
I20260812 06:19:53.676503 31750 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.025s	user 0.001s	sys 0.000s
I20260812 06:19:53.677364 31750 tablet_server.cc:179] TabletServer@127.31.1.129:0 shutting down...
I20260812 06:19:53.713172 32290 maintenance_manager.cc:643] P a7c90e037d3343caa416e8e17f24ff94: FlushDeltaMemStoresOp(b61b0679b25e409d93dce3c2bf1d98ff) complete. Timing: real 0.055s	user 0.039s	sys 0.016s Metrics: {"bytes_written":20512314,"delete_count":0,"lbm_write_time_us":24213,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:53.713901 31750 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:53.714179 31750 tablet_replica.cc:333] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94: stopping tablet replica
I20260812 06:19:53.714329 31750 raft_consensus.cc:2243] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:53.714519 31750 raft_consensus.cc:2272] T b61b0679b25e409d93dce3c2bf1d98ff P a7c90e037d3343caa416e8e17f24ff94 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:53.717876 31750 tablet_server.cc:196] TabletServer@127.31.1.129:0 shutdown complete.
I20260812 06:19:53.720683 31750 master.cc:562] Master@127.31.1.190:37219 shutting down...
I20260812 06:19:53.724316 31750 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 6038ec2f89c44ff5863cba22512aa78f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:53.724516 31750 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 6038ec2f89c44ff5863cba22512aa78f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:53.724633 31750 tablet_replica.cc:333] T 00000000000000000000000000000000 P 6038ec2f89c44ff5863cba22512aa78f: stopping tablet replica
I20260812 06:19:53.737164 31750 master.cc:584] Master@127.31.1.190:37219 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5430 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11003 ms total)

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