[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:18:19.186074 19443 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.18.252.254:39763
I20260812 06:18:19.187167 19443 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:18:19.187813 19443 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:19.195518 19453 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:19.195717 19449 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:19.195465 19443 server_base.cc:1061] running on GCE node
W20260812 06:18:19.195497 19450 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:19.196502 19443 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:19.196659 19443 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:19.196702 19443 hybrid_clock.cc:648] HybridClock initialized: now 1786515499196699 us; error 0 us; skew 500 ppm
I20260812 06:18:19.199004 19443 webserver.cc:533] Webserver started at http://127.18.252.254:40597/ using document root <none> and password file <none>
I20260812 06:18:19.199608 19443 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:19.199676 19443 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:19.199888 19443 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:19.201838 19443 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/master-0-root/instance:
uuid: "afc8eeefeceb432487edf9623d65a30a"
format_stamp: "Formatted at 2026-08-12 06:18:19 on dist-test-slave-rnrw"
I20260812 06:18:19.206594 19443 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.005s	sys 0.000s
I20260812 06:18:19.209290 19458 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:19.210595 19443 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:19.210722 19443 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/master-0-root
uuid: "afc8eeefeceb432487edf9623d65a30a"
format_stamp: "Formatted at 2026-08-12 06:18:19 on dist-test-slave-rnrw"
I20260812 06:18:19.210883 19443 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:19.230680 19443 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:19.231455 19443 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:18:19.231659 19443 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:19.240828 19443 rpc_server.cc:307] RPC server started. Bound to: 127.18.252.254:39763
I20260812 06:18:19.240841 19516 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.18.252.254:39763 every 8 connection(s)
I20260812 06:18:19.243539 19517 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:19.250560 19517 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P afc8eeefeceb432487edf9623d65a30a: Bootstrap starting.
I20260812 06:18:19.253309 19517 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P afc8eeefeceb432487edf9623d65a30a: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:19.254390 19517 log.cc:826] T 00000000000000000000000000000000 P afc8eeefeceb432487edf9623d65a30a: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:19.256925 19517 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P afc8eeefeceb432487edf9623d65a30a: No bootstrap required, opened a new log
I20260812 06:18:19.260426 19517 raft_consensus.cc:359] T 00000000000000000000000000000000 P afc8eeefeceb432487edf9623d65a30a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "afc8eeefeceb432487edf9623d65a30a" member_type: VOTER }
I20260812 06:18:19.260710 19517 raft_consensus.cc:385] T 00000000000000000000000000000000 P afc8eeefeceb432487edf9623d65a30a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:19.260761 19517 raft_consensus.cc:740] T 00000000000000000000000000000000 P afc8eeefeceb432487edf9623d65a30a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: afc8eeefeceb432487edf9623d65a30a, State: Initialized, Role: FOLLOWER
I20260812 06:18:19.261390 19517 consensus_queue.cc:260] T 00000000000000000000000000000000 P afc8eeefeceb432487edf9623d65a30a [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: "afc8eeefeceb432487edf9623d65a30a" member_type: VOTER }
I20260812 06:18:19.261554 19517 raft_consensus.cc:399] T 00000000000000000000000000000000 P afc8eeefeceb432487edf9623d65a30a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:19.261608 19517 raft_consensus.cc:493] T 00000000000000000000000000000000 P afc8eeefeceb432487edf9623d65a30a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:19.261749 19517 raft_consensus.cc:3060] T 00000000000000000000000000000000 P afc8eeefeceb432487edf9623d65a30a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:19.262969 19517 raft_consensus.cc:515] T 00000000000000000000000000000000 P afc8eeefeceb432487edf9623d65a30a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "afc8eeefeceb432487edf9623d65a30a" member_type: VOTER }
I20260812 06:18:19.263494 19517 leader_election.cc:304] T 00000000000000000000000000000000 P afc8eeefeceb432487edf9623d65a30a [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: afc8eeefeceb432487edf9623d65a30a; no voters: 
I20260812 06:18:19.263856 19517 leader_election.cc:290] T 00000000000000000000000000000000 P afc8eeefeceb432487edf9623d65a30a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:19.264102 19520 raft_consensus.cc:2804] T 00000000000000000000000000000000 P afc8eeefeceb432487edf9623d65a30a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:19.264458 19520 raft_consensus.cc:697] T 00000000000000000000000000000000 P afc8eeefeceb432487edf9623d65a30a [term 1 LEADER]: Becoming Leader. State: Replica: afc8eeefeceb432487edf9623d65a30a, State: Running, Role: LEADER
I20260812 06:18:19.264912 19520 consensus_queue.cc:237] T 00000000000000000000000000000000 P afc8eeefeceb432487edf9623d65a30a [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: "afc8eeefeceb432487edf9623d65a30a" member_type: VOTER }
I20260812 06:18:19.265112 19517 sys_catalog.cc:565] T 00000000000000000000000000000000 P afc8eeefeceb432487edf9623d65a30a [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:19.267282 19523 sys_catalog.cc:455] T 00000000000000000000000000000000 P afc8eeefeceb432487edf9623d65a30a [sys.catalog]: SysCatalogTable state changed. Reason: New leader afc8eeefeceb432487edf9623d65a30a. Latest consensus state: current_term: 1 leader_uuid: "afc8eeefeceb432487edf9623d65a30a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "afc8eeefeceb432487edf9623d65a30a" member_type: VOTER } }
I20260812 06:18:19.267335 19522 sys_catalog.cc:455] T 00000000000000000000000000000000 P afc8eeefeceb432487edf9623d65a30a [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "afc8eeefeceb432487edf9623d65a30a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "afc8eeefeceb432487edf9623d65a30a" member_type: VOTER } }
I20260812 06:18:19.267422 19523 sys_catalog.cc:458] T 00000000000000000000000000000000 P afc8eeefeceb432487edf9623d65a30a [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:19.267477 19522 sys_catalog.cc:458] T 00000000000000000000000000000000 P afc8eeefeceb432487edf9623d65a30a [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:19.267874 19532 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:19.270392 19532 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:19.270705 19443 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:19.276247 19532 catalog_manager.cc:1383] Generated new cluster ID: 74a2bb2a51aa437faeec3f44d4c3181d
I20260812 06:18:19.276345 19532 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:19.291492 19532 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:19.292482 19532 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:19.309547 19532 catalog_manager.cc:6092] T 00000000000000000000000000000000 P afc8eeefeceb432487edf9623d65a30a: Generated new TSK 0
I20260812 06:18:19.310346 19532 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:19.336295 19443 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:19.340180 19544 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:19.340201 19543 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:19.340358 19443 server_base.cc:1061] running on GCE node
W20260812 06:18:19.340201 19548 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:19.340931 19443 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:19.340989 19443 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:19.341006 19443 hybrid_clock.cc:648] HybridClock initialized: now 1786515499341007 us; error 0 us; skew 500 ppm
I20260812 06:18:19.342371 19443 webserver.cc:533] Webserver started at http://127.18.252.193:33109/ using document root <none> and password file <none>
I20260812 06:18:19.342687 19443 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:19.342800 19443 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:19.342903 19443 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:19.343367 19443 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root/instance:
uuid: "cf6761f624a842a0935ee4b2a53fa5c0"
format_stamp: "Formatted at 2026-08-12 06:18:19 on dist-test-slave-rnrw"
I20260812 06:18:19.345212 19443 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:19.346369 19554 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:19.346697 19443 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:19.346779 19443 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root
uuid: "cf6761f624a842a0935ee4b2a53fa5c0"
format_stamp: "Formatted at 2026-08-12 06:18:19 on dist-test-slave-rnrw"
I20260812 06:18:19.346887 19443 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:19.356276 19443 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:19.356935 19443 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:19.357616 19443 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:19.358682 19443 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:19.358742 19443 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:19.359004 19443 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:19.359091 19443 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:19.367368 19443 rpc_server.cc:307] RPC server started. Bound to: 127.18.252.193:42415
I20260812 06:18:19.367471 19626 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.18.252.193:42415 every 8 connection(s)
I20260812 06:18:19.385759 19627 heartbeater.cc:344] Connected to a master server at 127.18.252.254:39763
I20260812 06:18:19.386135 19627 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:19.386758 19627 heartbeater.cc:507] Master 127.18.252.254:39763 requested a full tablet report, sending...
I20260812 06:18:19.388497 19477 ts_manager.cc:194] Registered new tserver with Master: cf6761f624a842a0935ee4b2a53fa5c0 (127.18.252.193:42415)
I20260812 06:18:19.388797 19443 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.020636208s
I20260812 06:18:19.390298 19477 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:37236
I20260812 06:18:19.401201 19477 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:37250:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:19.419454 19584 tablet_service.cc:1511] Processing CreateTablet for tablet 483a4f298c494858ad8a4e6b1ed74a00 (DEFAULT_TABLE table=heavy-update-compaction-test [id=a78b45a94ccc449ca9b49b4e2ee60922]), partition=
I20260812 06:18:19.420044 19584 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 483a4f298c494858ad8a4e6b1ed74a00. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:19.422618 19641 tablet_bootstrap.cc:492] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Bootstrap starting.
I20260812 06:18:19.424096 19641 tablet_bootstrap.cc:654] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:19.425690 19641 tablet_bootstrap.cc:492] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: No bootstrap required, opened a new log
I20260812 06:18:19.425848 19641 ts_tablet_manager.cc:1403] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Time spent bootstrapping tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:18:19.426623 19641 raft_consensus.cc:359] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cf6761f624a842a0935ee4b2a53fa5c0" member_type: VOTER last_known_addr { host: "127.18.252.193" port: 42415 } }
I20260812 06:18:19.426764 19641 raft_consensus.cc:385] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:19.426823 19641 raft_consensus.cc:740] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: cf6761f624a842a0935ee4b2a53fa5c0, State: Initialized, Role: FOLLOWER
I20260812 06:18:19.426988 19641 consensus_queue.cc:260] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0 [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: "cf6761f624a842a0935ee4b2a53fa5c0" member_type: VOTER last_known_addr { host: "127.18.252.193" port: 42415 } }
I20260812 06:18:19.427084 19641 raft_consensus.cc:399] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:19.427114 19641 raft_consensus.cc:493] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:19.427189 19641 raft_consensus.cc:3060] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:19.428278 19641 raft_consensus.cc:515] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cf6761f624a842a0935ee4b2a53fa5c0" member_type: VOTER last_known_addr { host: "127.18.252.193" port: 42415 } }
I20260812 06:18:19.428486 19641 leader_election.cc:304] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0 [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: cf6761f624a842a0935ee4b2a53fa5c0; no voters: 
I20260812 06:18:19.428778 19641 leader_election.cc:290] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:19.428965 19643 raft_consensus.cc:2804] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:19.429267 19641 ts_tablet_manager.cc:1434] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.001s
I20260812 06:18:19.429519 19627 heartbeater.cc:499] Master 127.18.252.254:39763 was elected leader, sending a full tablet report...
I20260812 06:18:19.431452 19643 raft_consensus.cc:697] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0 [term 1 LEADER]: Becoming Leader. State: Replica: cf6761f624a842a0935ee4b2a53fa5c0, State: Running, Role: LEADER
I20260812 06:18:19.431715 19643 consensus_queue.cc:237] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0 [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: "cf6761f624a842a0935ee4b2a53fa5c0" member_type: VOTER last_known_addr { host: "127.18.252.193" port: 42415 } }
I20260812 06:18:19.435742 19477 catalog_manager.cc:5719] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0 reported cstate change: term changed from 0 to 1, leader changed from <none> to cf6761f624a842a0935ee4b2a53fa5c0 (127.18.252.193). New cstate: current_term: 1 leader_uuid: "cf6761f624a842a0935ee4b2a53fa5c0" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cf6761f624a842a0935ee4b2a53fa5c0" member_type: VOTER last_known_addr { host: "127.18.252.193" port: 42415 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:19.507242 19443 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.065s	user 0.021s	sys 0.008s
I20260812 06:18:19.619112 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushMRSOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=11.117440
I20260812 06:18:19.785948 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushMRSOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.166s	user 0.124s	sys 0.027s Metrics: {"bytes_written":11897249,"cfile_init":1,"compiler_manager_pool.queue_time_us":232,"delete_count":0,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":255,"dirs.run_wall_time_us":1011,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38034,"lbm_writes_lt_1ms":557,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":75648,"thread_start_us":133,"threads_started":1,"update_count":1450}
I20260812 06:18:19.787343 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling LogGCOp(483a4f298c494858ad8a4e6b1ed74a00): free 8725963 bytes of WAL
I20260812 06:18:19.787748 19559 log_reader.cc:385] T 483a4f298c494858ad8a4e6b1ed74a00: removed 1 log segments from log reader
I20260812 06:18:19.787828 19559 log.cc:1079] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/483a4f298c494858ad8a4e6b1ed74a00/wal-000000001 (ops 1-6)
I20260812 06:18:19.790820 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: LogGCOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:19.791235 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling UndoDeltaBlockGCOp(483a4f298c494858ad8a4e6b1ed74a00): 8616791 bytes on disk
I20260812 06:18:19.791944 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: UndoDeltaBlockGCOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":84,"lbm_reads_lt_1ms":4}
I20260812 06:18:19.792440 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=2.188937
I20260812 06:18:19.819650 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.027s	user 0.017s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7456,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:19.820173 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=1.000000
I20260812 06:18:19.962232 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.142s	user 0.102s	sys 0.040s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20221071,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1506,"lbm_read_time_us":10568,"lbm_reads_lt_1ms":450,"lbm_write_time_us":25476,"lbm_writes_lt_1ms":433,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":3840,"thread_start_us":479,"threads_started":5,"update_count":1950}
I20260812 06:18:19.962975 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=10.126437
I20260812 06:18:20.014636 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.051s	user 0.025s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":22181,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:20.015450 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=2.188937
I20260812 06:18:20.036741 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.021s	user 0.017s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6946,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:20.037269 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=1.000000
I20260812 06:18:20.168998 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.132s	user 0.124s	sys 0.008s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":336,"lbm_read_time_us":8277,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25943,"lbm_writes_lt_1ms":443,"mutex_wait_us":53,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":25984,"update_count":2000}
I20260812 06:18:20.169610 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=11.118625
I20260812 06:18:20.225713 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.056s	user 0.019s	sys 0.035s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":20307,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:20.226514 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=2.188937
I20260812 06:18:20.245319 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.019s	user 0.014s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6893,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:20.245970 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=1.000000
I20260812 06:18:20.405969 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.160s	user 0.087s	sys 0.071s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":476,"lbm_read_time_us":11952,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25666,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6272,"update_count":2000}
I20260812 06:18:20.406515 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=10.126437
I20260812 06:18:20.451634 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.045s	user 0.029s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19767,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:20.452411 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=1.000000
I20260812 06:18:20.570434 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.118s	user 0.102s	sys 0.015s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":767,"lbm_read_time_us":7376,"lbm_reads_lt_1ms":363,"lbm_write_time_us":22023,"lbm_writes_lt_1ms":343,"mutex_wait_us":310,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":1500}
I20260812 06:18:20.571605 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=10.126437
I20260812 06:18:20.621255 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.049s	user 0.021s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17228,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:20.621841 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=2.188937
I20260812 06:18:20.633256 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4145,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:20.634009 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=1.000000
I20260812 06:18:20.771036 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.137s	user 0.097s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":365,"lbm_read_time_us":10187,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25540,"lbm_writes_lt_1ms":443,"mutex_wait_us":55,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7552,"update_count":2000}
I20260812 06:18:20.771595 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=10.126437
I20260812 06:18:20.819346 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.048s	user 0.016s	sys 0.028s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17002,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:20.820317 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=1.000000
I20260812 06:18:20.940788 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.120s	user 0.083s	sys 0.037s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1840,"lbm_read_time_us":8609,"lbm_reads_lt_1ms":363,"lbm_write_time_us":18923,"lbm_writes_lt_1ms":343,"mutex_wait_us":612,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":13056,"update_count":1500}
I20260812 06:18:20.941610 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=10.126437
I20260812 06:18:20.990473 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.049s	user 0.025s	sys 0.016s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":18833,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:20.990983 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=2.188937
I20260812 06:18:21.001715 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.011s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3967,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:21.002280 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=1.000000
I20260812 06:18:21.131067 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.129s	user 0.093s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631315,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":319,"lbm_read_time_us":9098,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23696,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2000}
I20260812 06:18:21.131821 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=10.126437
I20260812 06:18:21.168366 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.036s	user 0.011s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14533,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:21.169176 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushMRSOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=1.000000
I20260812 06:18:21.207772 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushMRSOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.038s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1193504,"cfile_init":1,"dirs.queue_time_us":90,"dirs.run_cpu_time_us":305,"dirs.run_wall_time_us":1817,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1628,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:21.208667 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=3.181125
I20260812 06:18:21.230178 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.021s	user 0.005s	sys 0.012s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7341,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:21.230777 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling LogGCOp(483a4f298c494858ad8a4e6b1ed74a00): free 124257184 bytes of WAL
I20260812 06:18:21.231031 19559 log_reader.cc:385] T 483a4f298c494858ad8a4e6b1ed74a00: removed 12 log segments from log reader
I20260812 06:18:21.231089 19559 log.cc:1079] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/483a4f298c494858ad8a4e6b1ed74a00/wal-000000002 (ops 7-11)
I20260812 06:18:21.231153 19559 log.cc:1079] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/483a4f298c494858ad8a4e6b1ed74a00/wal-000000003 (ops 12-16)
I20260812 06:18:21.231204 19559 log.cc:1079] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/483a4f298c494858ad8a4e6b1ed74a00/wal-000000004 (ops 17-21)
I20260812 06:18:21.231274 19559 log.cc:1079] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/483a4f298c494858ad8a4e6b1ed74a00/wal-000000005 (ops 22-26)
I20260812 06:18:21.231344 19559 log.cc:1079] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/483a4f298c494858ad8a4e6b1ed74a00/wal-000000006 (ops 27-31)
I20260812 06:18:21.231388 19559 log.cc:1079] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/483a4f298c494858ad8a4e6b1ed74a00/wal-000000007 (ops 32-36)
I20260812 06:18:21.231436 19559 log.cc:1079] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/483a4f298c494858ad8a4e6b1ed74a00/wal-000000008 (ops 37-41)
I20260812 06:18:21.231474 19559 log.cc:1079] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/483a4f298c494858ad8a4e6b1ed74a00/wal-000000009 (ops 42-46)
I20260812 06:18:21.231524 19559 log.cc:1079] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/483a4f298c494858ad8a4e6b1ed74a00/wal-000000010 (ops 47-50)
I20260812 06:18:21.231566 19559 log.cc:1079] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/483a4f298c494858ad8a4e6b1ed74a00/wal-000000011 (ops 51-55)
I20260812 06:18:21.231612 19559 log.cc:1079] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/483a4f298c494858ad8a4e6b1ed74a00/wal-000000012 (ops 56-60)
I20260812 06:18:21.231657 19559 log.cc:1079] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/483a4f298c494858ad8a4e6b1ed74a00/wal-000000013 (ops 61-65)
I20260812 06:18:21.263062 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: LogGCOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.032s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:18:21.263551 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling UndoDeltaBlockGCOp(483a4f298c494858ad8a4e6b1ed74a00): 463 bytes on disk
I20260812 06:18:21.264213 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: UndoDeltaBlockGCOp(483a4f298c494858ad8a4e6b1ed74a00) 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:18:21.264840 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=2.188937
I20260812 06:18:21.278365 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.013s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4460,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:21.278858 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=2.188937
I20260812 06:18:21.289238 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4008,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:21.289770 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=1.000000
I20260812 06:18:21.512046 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.222s	user 0.165s	sys 0.048s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836364,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2948,"lbm_read_time_us":12789,"lbm_reads_lt_1ms":674,"lbm_write_time_us":47046,"lbm_writes_lt_1ms":643,"mutex_wait_us":2085,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":31104,"thread_start_us":95,"threads_started":1,"update_count":3000}
I20260812 06:18:21.512756 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=14.095187
I20260812 06:18:21.575142 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.062s	user 0.033s	sys 0.018s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":26682,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:21.575762 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=2.188937
I20260812 06:18:21.587924 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4527,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:21.588639 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=1.000000
I20260812 06:18:21.769429 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.181s	user 0.140s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733726,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":600,"lbm_read_time_us":10239,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32794,"lbm_writes_lt_1ms":543,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":31232,"update_count":2500}
I20260812 06:18:21.770272 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=14.095187
I20260812 06:18:21.816088 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.046s	user 0.033s	sys 0.009s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":21046,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:21.816668 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=1.000000
I20260812 06:18:21.953833 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.137s	user 0.100s	sys 0.036s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631195,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":306,"lbm_read_time_us":10840,"lbm_reads_lt_1ms":467,"lbm_write_time_us":22757,"lbm_writes_lt_1ms":443,"mutex_wait_us":31,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16896,"update_count":2000}
I20260812 06:18:21.954843 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=10.126437
I20260812 06:18:21.990034 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.035s	user 0.026s	sys 0.008s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14847,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:21.990658 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=2.188937
I20260812 06:18:22.007186 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.016s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6452,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.007758 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=1.000000
I20260812 06:18:22.144862 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.137s	user 0.113s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":196,"lbm_read_time_us":8598,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26904,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:22.149127 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=11.118625
I20260812 06:18:22.184271 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.035s	user 0.027s	sys 0.004s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14013,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:22.184955 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=2.188937
I20260812 06:18:22.201695 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.016s	user 0.014s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6591,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:22.202242 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=1.000000
I20260812 06:18:22.337610 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.135s	user 0.098s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":209,"lbm_read_time_us":8697,"lbm_reads_lt_1ms":468,"lbm_write_time_us":25734,"lbm_writes_lt_1ms":443,"mutex_wait_us":53,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:22.338402 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=10.126437
I20260812 06:18:22.401170 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.063s	user 0.029s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":39792,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:22.401911 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=2.188937
I20260812 06:18:22.419916 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.018s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5652,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.420853 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=1.000000
I20260812 06:18:22.557413 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.136s	user 0.092s	sys 0.045s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":184,"lbm_read_time_us":9390,"lbm_reads_lt_1ms":468,"lbm_write_time_us":28152,"lbm_writes_lt_1ms":443,"mutex_wait_us":44,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:22.558177 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=10.126437
I20260812 06:18:22.604357 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.046s	user 0.020s	sys 0.022s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15088,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:22.605173 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=2.188937
I20260812 06:18:22.617538 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.012s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4774,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.618072 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=1.000000
I20260812 06:18:22.780143 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.162s	user 0.115s	sys 0.046s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":278,"lbm_read_time_us":12268,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26675,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:22.785079 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=10.126437
I20260812 06:18:22.833629 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.048s	user 0.020s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17017,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:22.834360 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=2.188937
I20260812 06:18:22.846258 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4269,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:22.846968 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushMRSOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=1.000000
I20260812 06:18:22.883677 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushMRSOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.036s	user 0.035s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":89,"dirs.run_cpu_time_us":322,"dirs.run_wall_time_us":1984,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1674,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:22.884529 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling LogGCOp(483a4f298c494858ad8a4e6b1ed74a00): free 124710298 bytes of WAL
I20260812 06:18:22.884850 19559 log_reader.cc:385] T 483a4f298c494858ad8a4e6b1ed74a00: removed 12 log segments from log reader
I20260812 06:18:22.884896 19559 log.cc:1079] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/483a4f298c494858ad8a4e6b1ed74a00/wal-000000014 (ops 66-70)
I20260812 06:18:22.884927 19559 log.cc:1079] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/483a4f298c494858ad8a4e6b1ed74a00/wal-000000015 (ops 71-75)
I20260812 06:18:22.884997 19559 log.cc:1079] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/483a4f298c494858ad8a4e6b1ed74a00/wal-000000016 (ops 76-80)
I20260812 06:18:22.885043 19559 log.cc:1079] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/483a4f298c494858ad8a4e6b1ed74a00/wal-000000017 (ops 81-85)
I20260812 06:18:22.885103 19559 log.cc:1079] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/483a4f298c494858ad8a4e6b1ed74a00/wal-000000018 (ops 86-90)
I20260812 06:18:22.885154 19559 log.cc:1079] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/483a4f298c494858ad8a4e6b1ed74a00/wal-000000019 (ops 91-95)
I20260812 06:18:22.885195 19559 log.cc:1079] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/483a4f298c494858ad8a4e6b1ed74a00/wal-000000020 (ops 96-100)
I20260812 06:18:22.885237 19559 log.cc:1079] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/483a4f298c494858ad8a4e6b1ed74a00/wal-000000021 (ops 101-105)
I20260812 06:18:22.885274 19559 log.cc:1079] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/483a4f298c494858ad8a4e6b1ed74a00/wal-000000022 (ops 106-110)
I20260812 06:18:22.885313 19559 log.cc:1079] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/483a4f298c494858ad8a4e6b1ed74a00/wal-000000023 (ops 111-115)
I20260812 06:18:22.885354 19559 log.cc:1079] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/483a4f298c494858ad8a4e6b1ed74a00/wal-000000024 (ops 116-120)
I20260812 06:18:22.885394 19559 log.cc:1079] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/483a4f298c494858ad8a4e6b1ed74a00/wal-000000025 (ops 121-125)
I20260812 06:18:22.914227 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: LogGCOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.029s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:18:22.914701 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling UndoDeltaBlockGCOp(483a4f298c494858ad8a4e6b1ed74a00): 482 bytes on disk
I20260812 06:18:22.915166 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: UndoDeltaBlockGCOp(483a4f298c494858ad8a4e6b1ed74a00) 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:18:22.915817 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=4.173312
I20260812 06:18:22.941999 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.026s	user 0.012s	sys 0.012s Metrics: {"bytes_written":5866705,"delete_count":0,"lbm_write_time_us":8010,"lbm_writes_lt_1ms":146,"reinsert_count":0,"update_count":715}
I20260812 06:18:22.942603 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=1.196750
I20260812 06:18:22.951134 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.008s	user 0.006s	sys 0.001s Metrics: {"bytes_written":2338579,"delete_count":0,"lbm_write_time_us":3014,"lbm_writes_lt_1ms":60,"reinsert_count":0,"update_count":285}
I20260812 06:18:22.951689 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=1.000000
I20260812 06:18:23.168802 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.217s	user 0.120s	sys 0.092s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836334,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1080,"lbm_read_time_us":15079,"lbm_reads_lt_1ms":674,"lbm_write_time_us":37014,"lbm_writes_lt_1ms":643,"mutex_wait_us":364,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3584,"thread_start_us":224,"threads_started":1,"update_count":3000}
I20260812 06:18:23.169534 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=14.095187
I20260812 06:18:23.244342 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.075s	user 0.028s	sys 0.042s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":28725,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:23.244947 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=2.188937
I20260812 06:18:23.259588 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5555,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:23.260043 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=1.000000
I20260812 06:18:23.454192 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.194s	user 0.139s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":337,"lbm_read_time_us":13952,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30870,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:23.454828 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=14.095187
I20260812 06:18:23.514478 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.059s	user 0.029s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25756,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:23.515374 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=2.188937
I20260812 06:18:23.529384 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5636,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:23.529960 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=1.000000
I20260812 06:18:23.733716 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.204s	user 0.147s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":376,"lbm_read_time_us":13294,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35618,"lbm_writes_lt_1ms":543,"mutex_wait_us":150,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2500}
I20260812 06:18:23.734841 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=11.118625
I20260812 06:18:23.776839 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.042s	user 0.025s	sys 0.016s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":17603,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:23.777393 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=2.188937
I20260812 06:18:23.802459 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.024s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4987,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:23.803002 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=2.188937
I20260812 06:18:23.813868 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4083,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:23.814467 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=1.000000
I20260812 06:18:23.973874 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.159s	user 0.121s	sys 0.031s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733835,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":286,"lbm_read_time_us":10495,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29317,"lbm_writes_lt_1ms":543,"mutex_wait_us":45,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19200,"update_count":2500}
I20260812 06:18:23.974769 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=11.118625
I20260812 06:18:24.010519 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.036s	user 0.017s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14177,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:24.011209 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=2.188937
I20260812 06:18:24.033751 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.022s	user 0.004s	sys 0.007s Metrics: {"bytes_written":3815485,"delete_count":0,"lbm_write_time_us":4643,"lbm_writes_lt_1ms":96,"reinsert_count":0,"update_count":465}
I20260812 06:18:24.034301 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=2.188937
I20260812 06:18:24.044921 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.010s	user 0.002s	sys 0.008s Metrics: {"bytes_written":3979584,"delete_count":0,"lbm_write_time_us":4142,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:18:24.045594 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=1.000000
I20260812 06:18:24.203662 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.158s	user 0.126s	sys 0.028s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733839,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":61,"lbm_read_time_us":10079,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31718,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":2500}
I20260812 06:18:24.204439 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=11.118625
I20260812 06:18:24.250633 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.046s	user 0.024s	sys 0.017s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15990,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:24.251183 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=2.188937
I20260812 06:18:24.264257 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4885,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.264825 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=2.188937
I20260812 06:18:24.275460 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3840,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:24.276059 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=1.000000
I20260812 06:18:24.427696 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.151s	user 0.112s	sys 0.039s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733834,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":340,"lbm_read_time_us":10641,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31861,"lbm_writes_lt_1ms":543,"mutex_wait_us":108,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":2500}
I20260812 06:18:24.428413 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=10.126437
I20260812 06:18:24.480891 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.052s	user 0.017s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18256,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:24.481446 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=2.188937
I20260812 06:18:24.494046 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.012s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4524,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.494755 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushMRSOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=1.000000
I20260812 06:18:24.523972 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushMRSOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.029s	user 0.023s	sys 0.004s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":92,"dirs.run_cpu_time_us":222,"dirs.run_wall_time_us":1539,"drs_written":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1683,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:24.524802 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling LogGCOp(483a4f298c494858ad8a4e6b1ed74a00): free 133024698 bytes of WAL
I20260812 06:18:24.525086 19559 log_reader.cc:385] T 483a4f298c494858ad8a4e6b1ed74a00: removed 13 log segments from log reader
I20260812 06:18:24.525151 19559 log.cc:1079] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/483a4f298c494858ad8a4e6b1ed74a00/wal-000000026 (ops 126-130)
I20260812 06:18:24.525190 19559 log.cc:1079] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/483a4f298c494858ad8a4e6b1ed74a00/wal-000000027 (ops 131-135)
I20260812 06:18:24.525219 19559 log.cc:1079] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/483a4f298c494858ad8a4e6b1ed74a00/wal-000000028 (ops 136-140)
I20260812 06:18:24.525255 19559 log.cc:1079] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/483a4f298c494858ad8a4e6b1ed74a00/wal-000000029 (ops 141-145)
I20260812 06:18:24.525288 19559 log.cc:1079] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/483a4f298c494858ad8a4e6b1ed74a00/wal-000000030 (ops 146-150)
I20260812 06:18:24.525310 19559 log.cc:1079] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/483a4f298c494858ad8a4e6b1ed74a00/wal-000000031 (ops 151-154)
I20260812 06:18:24.525336 19559 log.cc:1079] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/483a4f298c494858ad8a4e6b1ed74a00/wal-000000032 (ops 155-159)
I20260812 06:18:24.525357 19559 log.cc:1079] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/483a4f298c494858ad8a4e6b1ed74a00/wal-000000033 (ops 160-164)
I20260812 06:18:24.525388 19559 log.cc:1079] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/483a4f298c494858ad8a4e6b1ed74a00/wal-000000034 (ops 165-169)
I20260812 06:18:24.525414 19559 log.cc:1079] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/483a4f298c494858ad8a4e6b1ed74a00/wal-000000035 (ops 170-174)
I20260812 06:18:24.525446 19559 log.cc:1079] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/483a4f298c494858ad8a4e6b1ed74a00/wal-000000036 (ops 175-179)
I20260812 06:18:24.525473 19559 log.cc:1079] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/483a4f298c494858ad8a4e6b1ed74a00/wal-000000037 (ops 180-184)
I20260812 06:18:24.525511 19559 log.cc:1079] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/483a4f298c494858ad8a4e6b1ed74a00/wal-000000038 (ops 185-189)
I20260812 06:18:24.559860 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: LogGCOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.035s	user 0.000s	sys 0.032s Metrics: {}
I20260812 06:18:24.560339 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling UndoDeltaBlockGCOp(483a4f298c494858ad8a4e6b1ed74a00): 483 bytes on disk
I20260812 06:18:24.560904 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: UndoDeltaBlockGCOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:18:24.561656 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=3.181125
I20260812 06:18:24.582269 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.020s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":5583,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:24.582809 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=2.188937
I20260812 06:18:24.593720 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4141,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:24.594507 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=1.000000
I20260812 06:18:24.777596 19443 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.270s	user 1.953s	sys 0.144s
I20260812 06:18:24.782981 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: MajorDeltaCompactionOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.188s	user 0.129s	sys 0.050s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836361,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1879,"lbm_read_time_us":12702,"lbm_reads_lt_1ms":674,"lbm_write_time_us":37314,"lbm_writes_lt_1ms":643,"mutex_wait_us":792,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":384,"thread_start_us":84,"threads_started":1,"update_count":3000}
I20260812 06:18:24.784490 19629 maintenance_manager.cc:419] P cf6761f624a842a0935ee4b2a53fa5c0: Scheduling FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00): perf score=14.095187
I20260812 06:18:24.829015 19443 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.051s	user 0.005s	sys 0.000s
I20260812 06:18:24.829785 19443 tablet_server.cc:179] TabletServer@127.18.252.193:0 shutting down...
I20260812 06:18:24.842531 19559 maintenance_manager.cc:643] P cf6761f624a842a0935ee4b2a53fa5c0: FlushDeltaMemStoresOp(483a4f298c494858ad8a4e6b1ed74a00) complete. Timing: real 0.058s	user 0.027s	sys 0.029s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26261,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:18:24.843333 19443 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:24.843734 19443 tablet_replica.cc:333] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0: stopping tablet replica
I20260812 06:18:24.843986 19443 raft_consensus.cc:2243] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:24.844273 19443 raft_consensus.cc:2272] T 483a4f298c494858ad8a4e6b1ed74a00 P cf6761f624a842a0935ee4b2a53fa5c0 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:24.859795 19443 tablet_server.cc:196] TabletServer@127.18.252.193:0 shutdown complete.
I20260812 06:18:24.865185 19443 master.cc:562] Master@127.18.252.254:39763 shutting down...
I20260812 06:18:24.869964 19443 raft_consensus.cc:2243] T 00000000000000000000000000000000 P afc8eeefeceb432487edf9623d65a30a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:24.870201 19443 raft_consensus.cc:2272] T 00000000000000000000000000000000 P afc8eeefeceb432487edf9623d65a30a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:24.870283 19443 tablet_replica.cc:333] T 00000000000000000000000000000000 P afc8eeefeceb432487edf9623d65a30a: stopping tablet replica
I20260812 06:18:24.882905 19443 master.cc:584] Master@127.18.252.254:39763 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5792 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:24.977504 19443 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.18.252.254:35389
I20260812 06:18:24.977903 19443 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:24.980273 19667 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:24.980304 19443 server_base.cc:1061] running on GCE node
W20260812 06:18:24.980351 19665 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:24.980522 19664 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:24.980819 19443 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:24.980886 19443 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:24.980912 19443 hybrid_clock.cc:648] HybridClock initialized: now 1786515504980911 us; error 0 us; skew 500 ppm
I20260812 06:18:24.981756 19443 webserver.cc:533] Webserver started at http://127.18.252.254:42479/ using document root <none> and password file <none>
I20260812 06:18:24.981932 19443 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:24.982045 19443 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:24.982151 19443 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:24.982566 19443 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/master-0-root/instance:
uuid: "e3e273976bd14908a496d47ff3681761"
format_stamp: "Formatted at 2026-08-12 06:18:24 on dist-test-slave-rnrw"
I20260812 06:18:24.984241 19443 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:24.985509 19672 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:24.985905 19443 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:24.986195 19443 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/master-0-root
uuid: "e3e273976bd14908a496d47ff3681761"
format_stamp: "Formatted at 2026-08-12 06:18:24 on dist-test-slave-rnrw"
I20260812 06:18:24.986334 19443 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:24.999399 19443 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:24.999852 19443 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:25.004513 19443 rpc_server.cc:307] RPC server started. Bound to: 127.18.252.254:35389
I20260812 06:18:25.006170 19735 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:25.006170 19734 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.18.252.254:35389 every 8 connection(s)
I20260812 06:18:25.021921 19735 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e3e273976bd14908a496d47ff3681761: Bootstrap starting.
I20260812 06:18:25.022881 19735 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P e3e273976bd14908a496d47ff3681761: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:25.024093 19735 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e3e273976bd14908a496d47ff3681761: No bootstrap required, opened a new log
I20260812 06:18:25.024636 19735 raft_consensus.cc:359] T 00000000000000000000000000000000 P e3e273976bd14908a496d47ff3681761 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e3e273976bd14908a496d47ff3681761" member_type: VOTER }
I20260812 06:18:25.024739 19735 raft_consensus.cc:385] T 00000000000000000000000000000000 P e3e273976bd14908a496d47ff3681761 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:25.024762 19735 raft_consensus.cc:740] T 00000000000000000000000000000000 P e3e273976bd14908a496d47ff3681761 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e3e273976bd14908a496d47ff3681761, State: Initialized, Role: FOLLOWER
I20260812 06:18:25.024931 19735 consensus_queue.cc:260] T 00000000000000000000000000000000 P e3e273976bd14908a496d47ff3681761 [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: "e3e273976bd14908a496d47ff3681761" member_type: VOTER }
I20260812 06:18:25.025005 19735 raft_consensus.cc:399] T 00000000000000000000000000000000 P e3e273976bd14908a496d47ff3681761 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:25.025058 19735 raft_consensus.cc:493] T 00000000000000000000000000000000 P e3e273976bd14908a496d47ff3681761 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:25.025126 19735 raft_consensus.cc:3060] T 00000000000000000000000000000000 P e3e273976bd14908a496d47ff3681761 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:25.025929 19735 raft_consensus.cc:515] T 00000000000000000000000000000000 P e3e273976bd14908a496d47ff3681761 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e3e273976bd14908a496d47ff3681761" member_type: VOTER }
I20260812 06:18:25.026072 19735 leader_election.cc:304] T 00000000000000000000000000000000 P e3e273976bd14908a496d47ff3681761 [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: e3e273976bd14908a496d47ff3681761; no voters: 
I20260812 06:18:25.026296 19735 leader_election.cc:290] T 00000000000000000000000000000000 P e3e273976bd14908a496d47ff3681761 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:25.026542 19740 raft_consensus.cc:2804] T 00000000000000000000000000000000 P e3e273976bd14908a496d47ff3681761 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:25.026715 19740 raft_consensus.cc:697] T 00000000000000000000000000000000 P e3e273976bd14908a496d47ff3681761 [term 1 LEADER]: Becoming Leader. State: Replica: e3e273976bd14908a496d47ff3681761, State: Running, Role: LEADER
I20260812 06:18:25.026824 19735 sys_catalog.cc:565] T 00000000000000000000000000000000 P e3e273976bd14908a496d47ff3681761 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:25.026845 19740 consensus_queue.cc:237] T 00000000000000000000000000000000 P e3e273976bd14908a496d47ff3681761 [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: "e3e273976bd14908a496d47ff3681761" member_type: VOTER }
I20260812 06:18:25.027302 19738 sys_catalog.cc:455] T 00000000000000000000000000000000 P e3e273976bd14908a496d47ff3681761 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "e3e273976bd14908a496d47ff3681761" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e3e273976bd14908a496d47ff3681761" member_type: VOTER } }
I20260812 06:18:25.027351 19741 sys_catalog.cc:455] T 00000000000000000000000000000000 P e3e273976bd14908a496d47ff3681761 [sys.catalog]: SysCatalogTable state changed. Reason: New leader e3e273976bd14908a496d47ff3681761. Latest consensus state: current_term: 1 leader_uuid: "e3e273976bd14908a496d47ff3681761" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e3e273976bd14908a496d47ff3681761" member_type: VOTER } }
I20260812 06:18:25.027468 19738 sys_catalog.cc:458] T 00000000000000000000000000000000 P e3e273976bd14908a496d47ff3681761 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:25.027488 19741 sys_catalog.cc:458] T 00000000000000000000000000000000 P e3e273976bd14908a496d47ff3681761 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:25.028229 19748 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:25.028964 19748 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:25.029362 19443 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:25.030900 19748 catalog_manager.cc:1383] Generated new cluster ID: 1b80beb698824ddea040ead6e2230e19
I20260812 06:18:25.030964 19748 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:25.065367 19748 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:25.065932 19748 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:25.073866 19748 catalog_manager.cc:6092] T 00000000000000000000000000000000 P e3e273976bd14908a496d47ff3681761: Generated new TSK 0
I20260812 06:18:25.074064 19748 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:25.094040 19443 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:25.096273 19759 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:25.096251 19443 server_base.cc:1061] running on GCE node
W20260812 06:18:25.096259 19762 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:25.096242 19760 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:25.096683 19443 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:25.096746 19443 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:25.096772 19443 hybrid_clock.cc:648] HybridClock initialized: now 1786515505096771 us; error 0 us; skew 500 ppm
I20260812 06:18:25.097675 19443 webserver.cc:533] Webserver started at http://127.18.252.193:44667/ using document root <none> and password file <none>
I20260812 06:18:25.097980 19443 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:25.098052 19443 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:25.098132 19443 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:25.098580 19443 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/instance:
uuid: "aa9118937153488aa132077949ea7a44"
format_stamp: "Formatted at 2026-08-12 06:18:25 on dist-test-slave-rnrw"
I20260812 06:18:25.100198 19443 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:25.101400 19768 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:25.101715 19443 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:25.101804 19443 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root
uuid: "aa9118937153488aa132077949ea7a44"
format_stamp: "Formatted at 2026-08-12 06:18:25 on dist-test-slave-rnrw"
I20260812 06:18:25.101887 19443 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:25.111550 19443 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:25.111992 19443 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:25.112363 19443 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:25.112891 19443 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:25.112948 19443 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:25.113008 19443 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:25.113031 19443 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:25.117416 19443 rpc_server.cc:307] RPC server started. Bound to: 127.18.252.193:44205
I20260812 06:18:25.117442 19837 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.18.252.193:44205 every 8 connection(s)
I20260812 06:18:25.127236 19838 heartbeater.cc:344] Connected to a master server at 127.18.252.254:35389
I20260812 06:18:25.127369 19838 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:25.127671 19838 heartbeater.cc:507] Master 127.18.252.254:35389 requested a full tablet report, sending...
I20260812 06:18:25.128422 19695 ts_manager.cc:194] Registered new tserver with Master: aa9118937153488aa132077949ea7a44 (127.18.252.193:44205)
I20260812 06:18:25.129074 19443 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011204997s
I20260812 06:18:25.129282 19695 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:53510
I20260812 06:18:25.137298 19695 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:53512:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:25.147269 19799 tablet_service.cc:1511] Processing CreateTablet for tablet 402cc7af997f4f2cafd8c2d9339e3e2a (DEFAULT_TABLE table=heavy-update-compaction-test [id=8350b7595e0f43f290251053a66e40a5]), partition=
I20260812 06:18:25.147564 19799 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 402cc7af997f4f2cafd8c2d9339e3e2a. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:25.149832 19853 tablet_bootstrap.cc:492] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Bootstrap starting.
I20260812 06:18:25.150897 19853 tablet_bootstrap.cc:654] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:25.152253 19853 tablet_bootstrap.cc:492] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: No bootstrap required, opened a new log
I20260812 06:18:25.152392 19853 ts_tablet_manager.cc:1403] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:25.153019 19853 raft_consensus.cc:359] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "aa9118937153488aa132077949ea7a44" member_type: VOTER last_known_addr { host: "127.18.252.193" port: 44205 } }
I20260812 06:18:25.153164 19853 raft_consensus.cc:385] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:25.153216 19853 raft_consensus.cc:740] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: aa9118937153488aa132077949ea7a44, State: Initialized, Role: FOLLOWER
I20260812 06:18:25.153369 19853 consensus_queue.cc:260] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44 [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: "aa9118937153488aa132077949ea7a44" member_type: VOTER last_known_addr { host: "127.18.252.193" port: 44205 } }
I20260812 06:18:25.153476 19853 raft_consensus.cc:399] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:25.153524 19853 raft_consensus.cc:493] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:25.153674 19853 raft_consensus.cc:3060] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:25.154500 19853 raft_consensus.cc:515] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "aa9118937153488aa132077949ea7a44" member_type: VOTER last_known_addr { host: "127.18.252.193" port: 44205 } }
I20260812 06:18:25.154678 19853 leader_election.cc:304] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44 [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: aa9118937153488aa132077949ea7a44; no voters: 
I20260812 06:18:25.154929 19853 leader_election.cc:290] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:25.155089 19855 raft_consensus.cc:2804] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:25.155298 19853 ts_tablet_manager.cc:1434] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:18:25.155325 19838 heartbeater.cc:499] Master 127.18.252.254:35389 was elected leader, sending a full tablet report...
I20260812 06:18:25.155354 19855 raft_consensus.cc:697] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44 [term 1 LEADER]: Becoming Leader. State: Replica: aa9118937153488aa132077949ea7a44, State: Running, Role: LEADER
I20260812 06:18:25.155546 19855 consensus_queue.cc:237] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44 [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: "aa9118937153488aa132077949ea7a44" member_type: VOTER last_known_addr { host: "127.18.252.193" port: 44205 } }
I20260812 06:18:25.157886 19694 catalog_manager.cc:5719] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44 reported cstate change: term changed from 0 to 1, leader changed from <none> to aa9118937153488aa132077949ea7a44 (127.18.252.193). New cstate: current_term: 1 leader_uuid: "aa9118937153488aa132077949ea7a44" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "aa9118937153488aa132077949ea7a44" member_type: VOTER last_known_addr { host: "127.18.252.193" port: 44205 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:25.222942 19443 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.059s	user 0.021s	sys 0.003s
I20260812 06:18:25.368723 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushMRSOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=19.054940
I20260812 06:18:25.535041 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushMRSOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.166s	user 0.119s	sys 0.043s Metrics: {"bytes_written":9640924,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":226,"dirs.run_wall_time_us":1151,"drs_written":1,"lbm_read_time_us":117,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42584,"lbm_writes_lt_1ms":692,"mutex_wait_us":1774,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1175}
I20260812 06:18:25.535933 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling LogGCOp(402cc7af997f4f2cafd8c2d9339e3e2a): free 20743831 bytes of WAL
I20260812 06:18:25.536347 19773 log_reader.cc:385] T 402cc7af997f4f2cafd8c2d9339e3e2a: removed 2 log segments from log reader
I20260812 06:18:25.536424 19773 log.cc:1079] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/402cc7af997f4f2cafd8c2d9339e3e2a/wal-000000001 (ops 1-6)
I20260812 06:18:25.536525 19773 log.cc:1079] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/402cc7af997f4f2cafd8c2d9339e3e2a/wal-000000002 (ops 7-11)
I20260812 06:18:25.542030 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: LogGCOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.006s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:18:25.542522 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling UndoDeltaBlockGCOp(402cc7af997f4f2cafd8c2d9339e3e2a): 16411392 bytes on disk
I20260812 06:18:25.542991 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: UndoDeltaBlockGCOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:18:25.543433 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=1.196750
I20260812 06:18:25.564092 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.020s	user 0.000s	sys 0.008s Metrics: {"bytes_written":2666779,"delete_count":0,"lbm_write_time_us":3919,"lbm_writes_lt_1ms":68,"reinsert_count":0,"update_count":325}
I20260812 06:18:25.564661 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=2.188937
I20260812 06:18:25.577097 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.012s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4596,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.577822 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling MajorDeltaCompactionOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=1.000000
I20260812 06:18:25.734153 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: MajorDeltaCompactionOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.156s	user 0.108s	sys 0.048s Metrics: {"cfile_cache_miss":433,"cfile_cache_miss_bytes":20672362,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":565,"lbm_read_time_us":12459,"lbm_reads_lt_1ms":469,"lbm_write_time_us":26459,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4864,"thread_start_us":351,"threads_started":5,"update_count":2000}
I20260812 06:18:25.734738 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=10.126437
I20260812 06:18:25.785871 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.051s	user 0.027s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":24829,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:25.786386 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=2.188937
I20260812 06:18:25.797883 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4636,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.798480 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling MajorDeltaCompactionOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=1.000000
I20260812 06:18:25.962777 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: MajorDeltaCompactionOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.164s	user 0.112s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1244,"lbm_read_time_us":12069,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28628,"lbm_writes_lt_1ms":443,"mutex_wait_us":321,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2000}
I20260812 06:18:25.963356 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=10.126437
I20260812 06:18:26.005438 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.042s	user 0.021s	sys 0.019s Metrics: {"bytes_written":12430563,"delete_count":0,"lbm_write_time_us":19677,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":305,"reinsert_count":0,"update_count":1515}
I20260812 06:18:26.007361 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=2.188937
I20260812 06:18:26.027994 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.020s	user 0.009s	sys 0.008s Metrics: {"bytes_written":3979584,"delete_count":0,"lbm_write_time_us":7229,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:18:26.028674 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling MajorDeltaCompactionOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=1.000000
I20260812 06:18:26.214594 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: MajorDeltaCompactionOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.186s	user 0.112s	sys 0.059s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672275,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":971,"lbm_read_time_us":10544,"lbm_reads_lt_1ms":464,"lbm_write_time_us":28588,"lbm_writes_lt_1ms":443,"mutex_wait_us":291,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14080,"update_count":2000}
I20260812 06:18:26.215281 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=14.095187
I20260812 06:18:26.275252 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.060s	user 0.029s	sys 0.021s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23332,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:26.275765 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=2.188937
I20260812 06:18:26.287925 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4421,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:26.288460 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling MajorDeltaCompactionOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=1.000000
I20260812 06:18:26.448577 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: MajorDeltaCompactionOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.160s	user 0.114s	sys 0.045s 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":446,"lbm_read_time_us":12947,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30049,"lbm_writes_lt_1ms":543,"mutex_wait_us":62,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":25088,"update_count":2500}
I20260812 06:18:26.449236 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=11.118625
I20260812 06:18:26.487746 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.038s	user 0.031s	sys 0.004s Metrics: {"bytes_written":12717743,"delete_count":0,"lbm_write_time_us":17105,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:26.488343 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=2.188937
I20260812 06:18:26.502177 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4936,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:26.502774 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling MajorDeltaCompactionOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=1.000000
I20260812 06:18:26.637084 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: MajorDeltaCompactionOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.134s	user 0.107s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":783,"lbm_read_time_us":10000,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25926,"lbm_writes_lt_1ms":443,"mutex_wait_us":254,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":27520,"update_count":2000}
I20260812 06:18:26.637748 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=10.126437
I20260812 06:18:26.694074 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.056s	user 0.024s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15926,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:26.694835 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=2.188937
I20260812 06:18:26.713855 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.019s	user 0.006s	sys 0.012s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":7156,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:26.714630 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling MajorDeltaCompactionOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=1.000000
I20260812 06:18:26.873785 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: MajorDeltaCompactionOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.159s	user 0.103s	sys 0.056s 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":257,"lbm_read_time_us":12855,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23895,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10240,"update_count":2000}
I20260812 06:18:26.874553 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=10.126437
I20260812 06:18:26.916972 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.042s	user 0.030s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17453,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:26.917479 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=2.188937
I20260812 06:18:26.930285 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.013s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4275,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:26.931371 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushMRSOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=1.000000
I20260812 06:18:26.962899 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushMRSOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.031s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":257,"dirs.run_wall_time_us":1807,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1616,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:26.963613 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling LogGCOp(402cc7af997f4f2cafd8c2d9339e3e2a): free 115943242 bytes of WAL
I20260812 06:18:26.963873 19773 log_reader.cc:385] T 402cc7af997f4f2cafd8c2d9339e3e2a: removed 11 log segments from log reader
I20260812 06:18:26.963939 19773 log.cc:1079] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/402cc7af997f4f2cafd8c2d9339e3e2a/wal-000000003 (ops 12-16)
I20260812 06:18:26.963994 19773 log.cc:1079] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/402cc7af997f4f2cafd8c2d9339e3e2a/wal-000000004 (ops 17-21)
I20260812 06:18:26.964046 19773 log.cc:1079] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/402cc7af997f4f2cafd8c2d9339e3e2a/wal-000000005 (ops 22-26)
I20260812 06:18:26.964087 19773 log.cc:1079] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/402cc7af997f4f2cafd8c2d9339e3e2a/wal-000000006 (ops 27-31)
I20260812 06:18:26.964156 19773 log.cc:1079] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/402cc7af997f4f2cafd8c2d9339e3e2a/wal-000000007 (ops 32-36)
I20260812 06:18:26.964196 19773 log.cc:1079] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/402cc7af997f4f2cafd8c2d9339e3e2a/wal-000000008 (ops 37-41)
I20260812 06:18:26.964233 19773 log.cc:1079] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/402cc7af997f4f2cafd8c2d9339e3e2a/wal-000000009 (ops 42-46)
I20260812 06:18:26.964304 19773 log.cc:1079] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/402cc7af997f4f2cafd8c2d9339e3e2a/wal-000000010 (ops 47-51)
I20260812 06:18:26.964329 19773 log.cc:1079] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/402cc7af997f4f2cafd8c2d9339e3e2a/wal-000000011 (ops 52-56)
I20260812 06:18:26.964362 19773 log.cc:1079] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/402cc7af997f4f2cafd8c2d9339e3e2a/wal-000000012 (ops 57-61)
I20260812 06:18:26.964403 19773 log.cc:1079] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/402cc7af997f4f2cafd8c2d9339e3e2a/wal-000000013 (ops 62-66)
I20260812 06:18:26.990365 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: LogGCOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.027s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:26.990852 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=3.181125
I20260812 06:18:27.016919 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.026s	user 0.014s	sys 0.012s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5560,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:27.017477 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=2.188937
I20260812 06:18:27.028059 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4072,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:27.028646 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling UndoDeltaBlockGCOp(402cc7af997f4f2cafd8c2d9339e3e2a): 460 bytes on disk
I20260812 06:18:27.029105 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: UndoDeltaBlockGCOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:18:27.029563 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling MajorDeltaCompactionOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=1.000000
I20260812 06:18:27.251787 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: MajorDeltaCompactionOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.222s	user 0.145s	sys 0.077s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":546,"lbm_read_time_us":15657,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36200,"lbm_writes_lt_1ms":643,"mutex_wait_us":69,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2048,"thread_start_us":85,"threads_started":1,"update_count":3000}
I20260812 06:18:27.256711 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=14.095187
I20260812 06:18:27.323695 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.067s	user 0.028s	sys 0.035s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":25599,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:27.324317 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=2.188937
I20260812 06:18:27.336917 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.012s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5149,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:27.337431 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling MajorDeltaCompactionOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=1.000000
I20260812 06:18:27.532248 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: MajorDeltaCompactionOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.195s	user 0.117s	sys 0.071s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1278,"lbm_read_time_us":16623,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28277,"lbm_writes_lt_1ms":543,"mutex_wait_us":306,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13312,"update_count":2500}
I20260812 06:18:27.533214 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=14.095187
I20260812 06:18:27.599020 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.066s	user 0.027s	sys 0.033s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22603,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:27.599586 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=2.188937
I20260812 06:18:27.612089 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4910,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:27.612723 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling MajorDeltaCompactionOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=1.000000
I20260812 06:18:27.806998 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: MajorDeltaCompactionOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.194s	user 0.117s	sys 0.069s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":186,"lbm_read_time_us":13762,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29679,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16256,"update_count":2500}
I20260812 06:18:27.807781 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=14.095187
I20260812 06:18:27.867295 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.059s	user 0.033s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":29342,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:27.867925 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=2.188937
I20260812 06:18:27.880018 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4631,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:27.880707 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling MajorDeltaCompactionOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=1.000000
I20260812 06:18:28.081581 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: MajorDeltaCompactionOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.201s	user 0.160s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":241,"lbm_read_time_us":12398,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32487,"lbm_writes_lt_1ms":543,"mutex_wait_us":69,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":2500}
I20260812 06:18:28.082651 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=14.095187
I20260812 06:18:28.140687 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.058s	user 0.035s	sys 0.019s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24570,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:28.141211 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=2.188937
I20260812 06:18:28.153024 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4299,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.153566 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling MajorDeltaCompactionOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=1.000000
I20260812 06:18:28.314829 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: MajorDeltaCompactionOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.161s	user 0.120s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":229,"lbm_read_time_us":12921,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28681,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":40064,"update_count":2500}
I20260812 06:18:28.315747 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=11.118625
I20260812 06:18:28.351585 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.036s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12717738,"delete_count":0,"lbm_write_time_us":15159,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:28.352288 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=2.188937
I20260812 06:18:28.368615 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.016s	user 0.013s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6175,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:28.369310 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling MajorDeltaCompactionOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=1.000000
I20260812 06:18:28.513782 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: MajorDeltaCompactionOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.144s	user 0.130s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672271,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":329,"lbm_read_time_us":10651,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26402,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19328,"update_count":2000}
I20260812 06:18:28.515029 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=10.126437
I20260812 06:18:28.562572 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.047s	user 0.030s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16198,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:28.563176 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=2.188937
I20260812 06:18:28.575114 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4609,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.575827 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushMRSOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=1.000000
I20260812 06:18:28.611076 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushMRSOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.035s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":260,"dirs.run_wall_time_us":1485,"drs_written":1,"lbm_read_time_us":110,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2050,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:28.611768 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling LogGCOp(402cc7af997f4f2cafd8c2d9339e3e2a): free 129320502 bytes of WAL
I20260812 06:18:28.612018 19773 log_reader.cc:385] T 402cc7af997f4f2cafd8c2d9339e3e2a: removed 13 log segments from log reader
I20260812 06:18:28.612066 19773 log.cc:1079] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/402cc7af997f4f2cafd8c2d9339e3e2a/wal-000000014 (ops 67-71)
I20260812 06:18:28.612118 19773 log.cc:1079] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/402cc7af997f4f2cafd8c2d9339e3e2a/wal-000000015 (ops 72-76)
I20260812 06:18:28.612164 19773 log.cc:1079] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/402cc7af997f4f2cafd8c2d9339e3e2a/wal-000000016 (ops 77-81)
I20260812 06:18:28.612191 19773 log.cc:1079] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/402cc7af997f4f2cafd8c2d9339e3e2a/wal-000000017 (ops 82-86)
I20260812 06:18:28.612237 19773 log.cc:1079] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/402cc7af997f4f2cafd8c2d9339e3e2a/wal-000000018 (ops 87-90)
I20260812 06:18:28.612267 19773 log.cc:1079] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/402cc7af997f4f2cafd8c2d9339e3e2a/wal-000000019 (ops 91-95)
I20260812 06:18:28.612301 19773 log.cc:1079] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/402cc7af997f4f2cafd8c2d9339e3e2a/wal-000000020 (ops 96-100)
I20260812 06:18:28.612341 19773 log.cc:1079] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/402cc7af997f4f2cafd8c2d9339e3e2a/wal-000000021 (ops 101-104)
I20260812 06:18:28.612376 19773 log.cc:1079] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/402cc7af997f4f2cafd8c2d9339e3e2a/wal-000000022 (ops 105-109)
I20260812 06:18:28.612414 19773 log.cc:1079] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/402cc7af997f4f2cafd8c2d9339e3e2a/wal-000000023 (ops 110-114)
I20260812 06:18:28.612454 19773 log.cc:1079] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/402cc7af997f4f2cafd8c2d9339e3e2a/wal-000000024 (ops 115-119)
I20260812 06:18:28.612501 19773 log.cc:1079] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/402cc7af997f4f2cafd8c2d9339e3e2a/wal-000000025 (ops 120-124)
I20260812 06:18:28.612566 19773 log.cc:1079] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/402cc7af997f4f2cafd8c2d9339e3e2a/wal-000000026 (ops 125-129)
I20260812 06:18:28.643335 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: LogGCOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.031s	user 0.002s	sys 0.027s Metrics: {}
I20260812 06:18:28.643746 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=4.173312
I20260812 06:18:28.658442 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":5497489,"delete_count":0,"lbm_write_time_us":6026,"lbm_writes_lt_1ms":137,"reinsert_count":0,"update_count":670}
I20260812 06:18:28.658950 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling UndoDeltaBlockGCOp(402cc7af997f4f2cafd8c2d9339e3e2a): 473 bytes on disk
I20260812 06:18:28.659401 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: UndoDeltaBlockGCOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:18:28.659890 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=1.196750
I20260812 06:18:28.672235 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":2707805,"delete_count":0,"lbm_write_time_us":4187,"lbm_writes_lt_1ms":69,"reinsert_count":0,"update_count":330}
I20260812 06:18:28.672755 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling MajorDeltaCompactionOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=1.000000
I20260812 06:18:28.856884 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: MajorDeltaCompactionOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.184s	user 0.143s	sys 0.041s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877309,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1061,"lbm_read_time_us":13631,"lbm_reads_lt_1ms":666,"lbm_write_time_us":37267,"lbm_writes_lt_1ms":643,"mutex_wait_us":98,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10880,"thread_start_us":141,"threads_started":1,"update_count":3000}
I20260812 06:18:28.857576 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=14.095187
I20260812 06:18:28.913757 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.054s	user 0.025s	sys 0.027s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":23808,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:28.914310 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=2.188937
I20260812 06:18:28.926988 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.013s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4763,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.927569 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling MajorDeltaCompactionOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=1.000000
I20260812 06:18:29.095255 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: MajorDeltaCompactionOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.167s	user 0.114s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774692,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1032,"lbm_read_time_us":11526,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32173,"lbm_writes_lt_1ms":543,"mutex_wait_us":297,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19328,"update_count":2500}
I20260812 06:18:29.095901 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=13.103000
I20260812 06:18:29.146940 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.051s	user 0.025s	sys 0.023s Metrics: {"bytes_written":14727915,"delete_count":0,"lbm_write_time_us":22795,"lbm_writes_lt_1ms":362,"reinsert_count":0,"update_count":1795}
I20260812 06:18:29.147679 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=1.000000
I20260812 06:18:29.164815 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.017s	user 0.001s	sys 0.007s Metrics: {"bytes_written":2092431,"delete_count":0,"lbm_write_time_us":2450,"lbm_writes_lt_1ms":54,"reinsert_count":0,"update_count":255}
I20260812 06:18:29.165515 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=2.188937
I20260812 06:18:29.181313 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.015s	user 0.007s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5621,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:29.181983 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling MajorDeltaCompactionOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=1.000000
I20260812 06:18:29.369747 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: MajorDeltaCompactionOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.188s	user 0.131s	sys 0.052s 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":938,"lbm_read_time_us":13593,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32390,"lbm_writes_lt_1ms":543,"mutex_wait_us":367,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17536,"update_count":2500}
I20260812 06:18:29.370568 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=14.095187
I20260812 06:18:29.430649 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.060s	user 0.023s	sys 0.028s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23929,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:29.431207 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=2.188937
I20260812 06:18:29.443580 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4427,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.444098 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling MajorDeltaCompactionOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=1.000000
I20260812 06:18:29.610123 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: MajorDeltaCompactionOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.166s	user 0.111s	sys 0.054s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":202,"lbm_read_time_us":11594,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29105,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16256,"update_count":2500}
I20260812 06:18:29.610770 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=14.095187
I20260812 06:18:29.672386 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.061s	user 0.026s	sys 0.032s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23022,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:18:29.673100 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=2.188937
I20260812 06:18:29.684432 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4341,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.687440 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling MajorDeltaCompactionOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=1.000000
I20260812 06:18:29.890363 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: MajorDeltaCompactionOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.203s	user 0.119s	sys 0.074s 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":411,"lbm_read_time_us":12825,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34938,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":25984,"update_count":2500}
I20260812 06:18:29.891244 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=14.095187
I20260812 06:18:29.959434 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.068s	user 0.030s	sys 0.036s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26056,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:29.960179 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=2.188937
I20260812 06:18:29.971462 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4540,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.971944 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling MajorDeltaCompactionOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=1.000000
I20260812 06:18:30.160460 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: MajorDeltaCompactionOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.188s	user 0.140s	sys 0.044s 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":783,"lbm_read_time_us":13060,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33342,"lbm_writes_lt_1ms":543,"mutex_wait_us":361,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2500}
I20260812 06:18:30.162457 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=11.118625
I20260812 06:18:30.202214 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.039s	user 0.015s	sys 0.022s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16699,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:30.203064 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=2.188937
I20260812 06:18:30.226572 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.023s	user 0.007s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4789,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:30.227051 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=2.188937
I20260812 06:18:30.248808 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.022s	user 0.013s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4246,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.249478 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushMRSOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=1.000000
I20260812 06:18:30.291345 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushMRSOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.042s	user 0.030s	sys 0.005s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":121,"dirs.run_cpu_time_us":199,"dirs.run_wall_time_us":1542,"drs_written":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1730,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:30.292124 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling LogGCOp(402cc7af997f4f2cafd8c2d9339e3e2a): free 133024609 bytes of WAL
I20260812 06:18:30.292371 19773 log_reader.cc:385] T 402cc7af997f4f2cafd8c2d9339e3e2a: removed 13 log segments from log reader
I20260812 06:18:30.292415 19773 log.cc:1079] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/402cc7af997f4f2cafd8c2d9339e3e2a/wal-000000027 (ops 130-134)
I20260812 06:18:30.292444 19773 log.cc:1079] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/402cc7af997f4f2cafd8c2d9339e3e2a/wal-000000028 (ops 135-138)
I20260812 06:18:30.292507 19773 log.cc:1079] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/402cc7af997f4f2cafd8c2d9339e3e2a/wal-000000029 (ops 139-143)
I20260812 06:18:30.292582 19773 log.cc:1079] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/402cc7af997f4f2cafd8c2d9339e3e2a/wal-000000030 (ops 144-148)
I20260812 06:18:30.292622 19773 log.cc:1079] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/402cc7af997f4f2cafd8c2d9339e3e2a/wal-000000031 (ops 149-153)
I20260812 06:18:30.292666 19773 log.cc:1079] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/402cc7af997f4f2cafd8c2d9339e3e2a/wal-000000032 (ops 154-158)
I20260812 06:18:30.292707 19773 log.cc:1079] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/402cc7af997f4f2cafd8c2d9339e3e2a/wal-000000033 (ops 159-163)
I20260812 06:18:30.292747 19773 log.cc:1079] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/402cc7af997f4f2cafd8c2d9339e3e2a/wal-000000034 (ops 164-168)
I20260812 06:18:30.292786 19773 log.cc:1079] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/402cc7af997f4f2cafd8c2d9339e3e2a/wal-000000035 (ops 169-172)
I20260812 06:18:30.292826 19773 log.cc:1079] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/402cc7af997f4f2cafd8c2d9339e3e2a/wal-000000036 (ops 173-177)
I20260812 06:18:30.292865 19773 log.cc:1079] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/402cc7af997f4f2cafd8c2d9339e3e2a/wal-000000037 (ops 178-182)
I20260812 06:18:30.292905 19773 log.cc:1079] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/402cc7af997f4f2cafd8c2d9339e3e2a/wal-000000038 (ops 183-187)
I20260812 06:18:30.292946 19773 log.cc:1079] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: Deleting log segment in path: /tmp/dist-test-taskaRoojx/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515499173701-19443-0/minicluster-data/ts-0-root/wals/402cc7af997f4f2cafd8c2d9339e3e2a/wal-000000039 (ops 188-193)
I20260812 06:18:30.324497 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: LogGCOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.032s	user 0.002s	sys 0.027s Metrics: {}
I20260812 06:18:30.325069 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=3.181125
I20260812 06:18:30.339635 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.014s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4430853,"delete_count":0,"lbm_write_time_us":5439,"lbm_writes_lt_1ms":111,"reinsert_count":0,"update_count":540}
I20260812 06:18:30.340101 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=2.188937
I20260812 06:18:30.353160 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.013s	user 0.009s	sys 0.003s Metrics: {"bytes_written":3774458,"delete_count":0,"lbm_write_time_us":4933,"lbm_writes_lt_1ms":95,"reinsert_count":0,"update_count":460}
I20260812 06:18:30.353704 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling MajorDeltaCompactionOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=1.000000
I20260812 06:18:30.497143 19443 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.274s	user 1.928s	sys 0.196s
I20260812 06:18:30.580432 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: MajorDeltaCompactionOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.227s	user 0.142s	sys 0.084s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979853,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":496,"lbm_read_time_us":15983,"lbm_reads_lt_1ms":771,"lbm_write_time_us":38814,"lbm_writes_lt_1ms":743,"mutex_wait_us":62,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":11008,"thread_start_us":92,"threads_started":1,"update_count":3500}
I20260812 06:18:30.582777 19839 maintenance_manager.cc:419] P aa9118937153488aa132077949ea7a44: Scheduling FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a): perf score=10.126437
I20260812 06:18:30.592928 19443 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.095s	user 0.003s	sys 0.000s
I20260812 06:18:30.593467 19443 tablet_server.cc:179] TabletServer@127.18.252.193:0 shutting down...
I20260812 06:18:30.630543 19773 maintenance_manager.cc:643] P aa9118937153488aa132077949ea7a44: FlushDeltaMemStoresOp(402cc7af997f4f2cafd8c2d9339e3e2a) complete. Timing: real 0.047s	user 0.019s	sys 0.026s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20805,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:30.631268 19443 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:30.631541 19443 tablet_replica.cc:333] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44: stopping tablet replica
I20260812 06:18:30.631719 19443 raft_consensus.cc:2243] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:30.631886 19443 raft_consensus.cc:2272] T 402cc7af997f4f2cafd8c2d9339e3e2a P aa9118937153488aa132077949ea7a44 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:30.637879 19443 tablet_server.cc:196] TabletServer@127.18.252.193:0 shutdown complete.
I20260812 06:18:30.641026 19443 master.cc:562] Master@127.18.252.254:35389 shutting down...
I20260812 06:18:30.645020 19443 raft_consensus.cc:2243] T 00000000000000000000000000000000 P e3e273976bd14908a496d47ff3681761 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:30.645242 19443 raft_consensus.cc:2272] T 00000000000000000000000000000000 P e3e273976bd14908a496d47ff3681761 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:30.645327 19443 tablet_replica.cc:333] T 00000000000000000000000000000000 P e3e273976bd14908a496d47ff3681761: stopping tablet replica
I20260812 06:18:30.657883 19443 master.cc:584] Master@127.18.252.254:35389 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5778 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11572 ms total)

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