[==========] 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:41.909621 24294 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.23.185.190:44015
I20260812 06:18:41.910760 24294 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:41.911393 24294 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:41.918035 24307 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:41.918035 24305 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:41.918213 24294 server_base.cc:1061] running on GCE node
W20260812 06:18:41.918344 24312 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:41.918874 24294 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:41.918992 24294 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:41.919057 24294 hybrid_clock.cc:648] HybridClock initialized: now 1786515521919054 us; error 0 us; skew 500 ppm
I20260812 06:18:41.920847 24294 webserver.cc:533] Webserver started at http://127.23.185.190:45677/ using document root <none> and password file <none>
I20260812 06:18:41.921404 24294 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:41.921494 24294 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:41.921756 24294 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:41.923424 24294 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/master-0-root/instance:
uuid: "8f08deb65b8e4a7994f53470a102d675"
format_stamp: "Formatted at 2026-08-12 06:18:41 on dist-test-slave-68xk"
I20260812 06:18:41.926873 24294 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.001s
I20260812 06:18:41.928952 24320 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:41.930054 24294 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:41.930192 24294 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/master-0-root
uuid: "8f08deb65b8e4a7994f53470a102d675"
format_stamp: "Formatted at 2026-08-12 06:18:41 on dist-test-slave-68xk"
I20260812 06:18:41.930306 24294 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-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:41.948354 24294 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:41.948954 24294 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:41.949132 24294 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:41.956950 24294 rpc_server.cc:307] RPC server started. Bound to: 127.23.185.190:44015
I20260812 06:18:41.957001 24391 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.185.190:44015 every 8 connection(s)
I20260812 06:18:41.959375 24392 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:41.964826 24392 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8f08deb65b8e4a7994f53470a102d675: Bootstrap starting.
I20260812 06:18:41.967247 24392 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 8f08deb65b8e4a7994f53470a102d675: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:41.968122 24392 log.cc:826] T 00000000000000000000000000000000 P 8f08deb65b8e4a7994f53470a102d675: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:41.969692 24392 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8f08deb65b8e4a7994f53470a102d675: No bootstrap required, opened a new log
I20260812 06:18:41.972334 24392 raft_consensus.cc:359] T 00000000000000000000000000000000 P 8f08deb65b8e4a7994f53470a102d675 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8f08deb65b8e4a7994f53470a102d675" member_type: VOTER }
I20260812 06:18:41.972491 24392 raft_consensus.cc:385] T 00000000000000000000000000000000 P 8f08deb65b8e4a7994f53470a102d675 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:41.972532 24392 raft_consensus.cc:740] T 00000000000000000000000000000000 P 8f08deb65b8e4a7994f53470a102d675 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8f08deb65b8e4a7994f53470a102d675, State: Initialized, Role: FOLLOWER
I20260812 06:18:41.973037 24392 consensus_queue.cc:260] T 00000000000000000000000000000000 P 8f08deb65b8e4a7994f53470a102d675 [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: "8f08deb65b8e4a7994f53470a102d675" member_type: VOTER }
I20260812 06:18:41.973162 24392 raft_consensus.cc:399] T 00000000000000000000000000000000 P 8f08deb65b8e4a7994f53470a102d675 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:41.973207 24392 raft_consensus.cc:493] T 00000000000000000000000000000000 P 8f08deb65b8e4a7994f53470a102d675 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:41.973285 24392 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 8f08deb65b8e4a7994f53470a102d675 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:41.973991 24392 raft_consensus.cc:515] T 00000000000000000000000000000000 P 8f08deb65b8e4a7994f53470a102d675 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8f08deb65b8e4a7994f53470a102d675" member_type: VOTER }
I20260812 06:18:41.974366 24392 leader_election.cc:304] T 00000000000000000000000000000000 P 8f08deb65b8e4a7994f53470a102d675 [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: 8f08deb65b8e4a7994f53470a102d675; no voters: 
I20260812 06:18:41.974699 24392 leader_election.cc:290] T 00000000000000000000000000000000 P 8f08deb65b8e4a7994f53470a102d675 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:41.974854 24396 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 8f08deb65b8e4a7994f53470a102d675 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:41.975102 24396 raft_consensus.cc:697] T 00000000000000000000000000000000 P 8f08deb65b8e4a7994f53470a102d675 [term 1 LEADER]: Becoming Leader. State: Replica: 8f08deb65b8e4a7994f53470a102d675, State: Running, Role: LEADER
I20260812 06:18:41.975505 24396 consensus_queue.cc:237] T 00000000000000000000000000000000 P 8f08deb65b8e4a7994f53470a102d675 [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: "8f08deb65b8e4a7994f53470a102d675" member_type: VOTER }
I20260812 06:18:41.975767 24392 sys_catalog.cc:565] T 00000000000000000000000000000000 P 8f08deb65b8e4a7994f53470a102d675 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:41.977415 24398 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8f08deb65b8e4a7994f53470a102d675 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 8f08deb65b8e4a7994f53470a102d675. Latest consensus state: current_term: 1 leader_uuid: "8f08deb65b8e4a7994f53470a102d675" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8f08deb65b8e4a7994f53470a102d675" member_type: VOTER } }
I20260812 06:18:41.977536 24398 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8f08deb65b8e4a7994f53470a102d675 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:41.977484 24397 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8f08deb65b8e4a7994f53470a102d675 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "8f08deb65b8e4a7994f53470a102d675" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8f08deb65b8e4a7994f53470a102d675" member_type: VOTER } }
I20260812 06:18:41.977591 24397 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8f08deb65b8e4a7994f53470a102d675 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:41.978049 24417 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:41.978281 24294 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:41.980347 24417 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:41.984922 24417 catalog_manager.cc:1383] Generated new cluster ID: 996a67df024d417496bd1694ab6e7b07
I20260812 06:18:41.984987 24417 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:41.995636 24417 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:41.996519 24417 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:42.002995 24417 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 8f08deb65b8e4a7994f53470a102d675: Generated new TSK 0
I20260812 06:18:42.003626 24417 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:42.011130 24294 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:42.013878 24428 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:42.013922 24430 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:42.013942 24435 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:42.014557 24294 server_base.cc:1061] running on GCE node
I20260812 06:18:42.014737 24294 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:42.014779 24294 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:42.014796 24294 hybrid_clock.cc:648] HybridClock initialized: now 1786515522014797 us; error 0 us; skew 500 ppm
I20260812 06:18:42.015714 24294 webserver.cc:533] Webserver started at http://127.23.185.129:46143/ using document root <none> and password file <none>
I20260812 06:18:42.015909 24294 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:42.015954 24294 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:42.016052 24294 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:42.016487 24294 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root/instance:
uuid: "25e2ac2d5c5a4040a0189d4f4eb12f26"
format_stamp: "Formatted at 2026-08-12 06:18:42 on dist-test-slave-68xk"
I20260812 06:18:42.018159 24294 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:42.019465 24441 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:42.019767 24294 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:42.019874 24294 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root
uuid: "25e2ac2d5c5a4040a0189d4f4eb12f26"
format_stamp: "Formatted at 2026-08-12 06:18:42 on dist-test-slave-68xk"
I20260812 06:18:42.019945 24294 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-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:42.024511 24294 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:42.024919 24294 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:42.025370 24294 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:42.026182 24294 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:42.026258 24294 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:42.026332 24294 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:42.026384 24294 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:42.033437 24294 rpc_server.cc:307] RPC server started. Bound to: 127.23.185.129:42781
I20260812 06:18:42.033473 24551 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.185.129:42781 every 8 connection(s)
I20260812 06:18:42.050731 24552 heartbeater.cc:344] Connected to a master server at 127.23.185.190:44015
I20260812 06:18:42.051028 24552 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:42.051522 24552 heartbeater.cc:507] Master 127.23.185.190:44015 requested a full tablet report, sending...
I20260812 06:18:42.052985 24343 ts_manager.cc:194] Registered new tserver with Master: 25e2ac2d5c5a4040a0189d4f4eb12f26 (127.23.185.129:42781)
I20260812 06:18:42.053062 24294 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.018957642s
I20260812 06:18:42.054221 24343 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:53002
I20260812 06:18:42.062726 24343 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:53012:
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:42.077142 24491 tablet_service.cc:1511] Processing CreateTablet for tablet ab0da943a7e7425d81ff9cfad8359cd6 (DEFAULT_TABLE table=heavy-update-compaction-test [id=66ebece8818d46cd9144d4bb488e55ac]), partition=
I20260812 06:18:42.077596 24491 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet ab0da943a7e7425d81ff9cfad8359cd6. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:42.080022 24576 tablet_bootstrap.cc:492] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Bootstrap starting.
I20260812 06:18:42.081017 24576 tablet_bootstrap.cc:654] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:42.082212 24576 tablet_bootstrap.cc:492] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: No bootstrap required, opened a new log
I20260812 06:18:42.082346 24576 ts_tablet_manager.cc:1403] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:42.082816 24576 raft_consensus.cc:359] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "25e2ac2d5c5a4040a0189d4f4eb12f26" member_type: VOTER last_known_addr { host: "127.23.185.129" port: 42781 } }
I20260812 06:18:42.082942 24576 raft_consensus.cc:385] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:42.082989 24576 raft_consensus.cc:740] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 25e2ac2d5c5a4040a0189d4f4eb12f26, State: Initialized, Role: FOLLOWER
I20260812 06:18:42.083151 24576 consensus_queue.cc:260] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26 [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: "25e2ac2d5c5a4040a0189d4f4eb12f26" member_type: VOTER last_known_addr { host: "127.23.185.129" port: 42781 } }
I20260812 06:18:42.083272 24576 raft_consensus.cc:399] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:42.083323 24576 raft_consensus.cc:493] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:42.083377 24576 raft_consensus.cc:3060] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:42.084270 24576 raft_consensus.cc:515] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "25e2ac2d5c5a4040a0189d4f4eb12f26" member_type: VOTER last_known_addr { host: "127.23.185.129" port: 42781 } }
I20260812 06:18:42.084438 24576 leader_election.cc:304] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26 [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: 25e2ac2d5c5a4040a0189d4f4eb12f26; no voters: 
I20260812 06:18:42.084687 24576 leader_election.cc:290] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:42.084787 24578 raft_consensus.cc:2804] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:42.084995 24578 raft_consensus.cc:697] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26 [term 1 LEADER]: Becoming Leader. State: Replica: 25e2ac2d5c5a4040a0189d4f4eb12f26, State: Running, Role: LEADER
I20260812 06:18:42.085083 24576 ts_tablet_manager.cc:1434] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:42.085603 24578 consensus_queue.cc:237] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26 [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: "25e2ac2d5c5a4040a0189d4f4eb12f26" member_type: VOTER last_known_addr { host: "127.23.185.129" port: 42781 } }
I20260812 06:18:42.086398 24552 heartbeater.cc:499] Master 127.23.185.190:44015 was elected leader, sending a full tablet report...
I20260812 06:18:42.089282 24343 catalog_manager.cc:5719] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26 reported cstate change: term changed from 0 to 1, leader changed from <none> to 25e2ac2d5c5a4040a0189d4f4eb12f26 (127.23.185.129). New cstate: current_term: 1 leader_uuid: "25e2ac2d5c5a4040a0189d4f4eb12f26" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "25e2ac2d5c5a4040a0189d4f4eb12f26" member_type: VOTER last_known_addr { host: "127.23.185.129" port: 42781 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:42.156476 24294 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.058s	user 0.018s	sys 0.008s
I20260812 06:18:42.285054 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushMRSOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=15.086190
I20260812 06:18:42.433000 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushMRSOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.148s	user 0.097s	sys 0.048s Metrics: {"bytes_written":11897249,"cfile_init":1,"compiler_manager_pool.queue_time_us":204,"delete_count":0,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":200,"dirs.run_wall_time_us":844,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":33254,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":115,"threads_started":1,"update_count":1450}
I20260812 06:18:42.434151 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling LogGCOp(ab0da943a7e7425d81ff9cfad8359cd6): free 20743880 bytes of WAL
I20260812 06:18:42.434473 24454 log_reader.cc:385] T ab0da943a7e7425d81ff9cfad8359cd6: removed 2 log segments from log reader
I20260812 06:18:42.434546 24454 log.cc:1079] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/ab0da943a7e7425d81ff9cfad8359cd6/wal-000000001 (ops 1-6)
I20260812 06:18:42.434666 24454 log.cc:1079] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/ab0da943a7e7425d81ff9cfad8359cd6/wal-000000002 (ops 7-11)
I20260812 06:18:42.440327 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: LogGCOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.006s	user 0.002s	sys 0.002s Metrics: {}
I20260812 06:18:42.440654 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling UndoDeltaBlockGCOp(ab0da943a7e7425d81ff9cfad8359cd6): 12719217 bytes on disk
I20260812 06:18:42.441221 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: UndoDeltaBlockGCOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4}
I20260812 06:18:42.441612 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=2.188937
I20260812 06:18:42.458882 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.017s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6547,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.459460 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=1.000000
I20260812 06:18:42.592774 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.133s	user 0.109s	sys 0.024s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262036,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":501,"lbm_read_time_us":9311,"lbm_reads_lt_1ms":454,"lbm_write_time_us":25222,"lbm_writes_lt_1ms":433,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":1664,"thread_start_us":310,"threads_started":5,"update_count":1950}
I20260812 06:18:42.593339 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=10.126437
I20260812 06:18:42.626652 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.033s	user 0.024s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13754,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:42.627116 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=1.000000
I20260812 06:18:42.734695 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.107s	user 0.085s	sys 0.020s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":993,"lbm_read_time_us":7338,"lbm_reads_lt_1ms":363,"lbm_write_time_us":20411,"lbm_writes_lt_1ms":343,"mutex_wait_us":22,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":27648,"update_count":1500}
I20260812 06:18:42.735404 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=10.126437
I20260812 06:18:42.792948 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.057s	user 0.006s	sys 0.033s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18217,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:42.793412 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=2.188937
I20260812 06:18:42.804368 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4385,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.804842 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=1.000000
I20260812 06:18:42.951174 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.146s	user 0.106s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":544,"lbm_read_time_us":11224,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24791,"lbm_writes_lt_1ms":443,"mutex_wait_us":230,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2000}
I20260812 06:18:42.951725 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=10.126437
I20260812 06:18:42.993656 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.042s	user 0.019s	sys 0.019s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":19043,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:42.994179 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=2.188937
I20260812 06:18:43.005801 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4236,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.012773 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=1.000000
I20260812 06:18:43.137578 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.125s	user 0.110s	sys 0.011s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":264,"lbm_read_time_us":8167,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25496,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:43.138190 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=10.126437
I20260812 06:18:43.192276 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.054s	user 0.024s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":22166,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:43.192744 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=2.188937
I20260812 06:18:43.203011 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4044,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.203436 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=1.000000
I20260812 06:18:43.324514 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.121s	user 0.097s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":993,"lbm_read_time_us":8643,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25428,"lbm_writes_lt_1ms":443,"mutex_wait_us":322,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:43.325022 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=10.126437
I20260812 06:18:43.368682 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.043s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15374,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:43.369146 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=2.188937
I20260812 06:18:43.380568 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4325,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.381191 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=1.000000
I20260812 06:18:43.498112 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.117s	user 0.111s	sys 0.003s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"lbm_read_time_us":7784,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22387,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:43.498889 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=10.126437
I20260812 06:18:43.551050 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.052s	user 0.020s	sys 0.031s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":18672,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:43.551522 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=2.188937
I20260812 06:18:43.562134 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4193,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.562645 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=1.000000
I20260812 06:18:43.721336 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.159s	user 0.099s	sys 0.057s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":243,"lbm_read_time_us":11221,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26690,"lbm_writes_lt_1ms":443,"mutex_wait_us":45,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:43.722375 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=10.126437
I20260812 06:18:43.767575 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.045s	user 0.024s	sys 0.017s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17929,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:43.768326 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushMRSOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=1.000000
I20260812 06:18:43.827916 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushMRSOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.059s	user 0.036s	sys 0.001s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":187,"dirs.run_wall_time_us":1058,"drs_written":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4,"lbm_write_time_us":4009,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":38,"peak_mem_usage":0,"rows_written":30,"spinlock_wait_cycles":14208}
I20260812 06:18:43.828717 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling LogGCOp(ab0da943a7e7425d81ff9cfad8359cd6): free 120553378 bytes of WAL
I20260812 06:18:43.828948 24454 log_reader.cc:385] T ab0da943a7e7425d81ff9cfad8359cd6: removed 12 log segments from log reader
I20260812 06:18:43.828994 24454 log.cc:1079] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/ab0da943a7e7425d81ff9cfad8359cd6/wal-000000003 (ops 12-16)
I20260812 06:18:43.829023 24454 log.cc:1079] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/ab0da943a7e7425d81ff9cfad8359cd6/wal-000000004 (ops 17-20)
I20260812 06:18:43.829092 24454 log.cc:1079] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/ab0da943a7e7425d81ff9cfad8359cd6/wal-000000005 (ops 21-25)
I20260812 06:18:43.829137 24454 log.cc:1079] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/ab0da943a7e7425d81ff9cfad8359cd6/wal-000000006 (ops 26-30)
I20260812 06:18:43.829188 24454 log.cc:1079] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/ab0da943a7e7425d81ff9cfad8359cd6/wal-000000007 (ops 31-34)
I20260812 06:18:43.829247 24454 log.cc:1079] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/ab0da943a7e7425d81ff9cfad8359cd6/wal-000000008 (ops 35-39)
I20260812 06:18:43.829288 24454 log.cc:1079] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/ab0da943a7e7425d81ff9cfad8359cd6/wal-000000009 (ops 40-44)
I20260812 06:18:43.829327 24454 log.cc:1079] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/ab0da943a7e7425d81ff9cfad8359cd6/wal-000000010 (ops 45-49)
I20260812 06:18:43.829366 24454 log.cc:1079] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/ab0da943a7e7425d81ff9cfad8359cd6/wal-000000011 (ops 50-54)
I20260812 06:18:43.829404 24454 log.cc:1079] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/ab0da943a7e7425d81ff9cfad8359cd6/wal-000000012 (ops 55-59)
I20260812 06:18:43.829447 24454 log.cc:1079] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/ab0da943a7e7425d81ff9cfad8359cd6/wal-000000013 (ops 60-64)
I20260812 06:18:43.829488 24454 log.cc:1079] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/ab0da943a7e7425d81ff9cfad8359cd6/wal-000000014 (ops 65-69)
I20260812 06:18:43.855417 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: LogGCOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:43.855904 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=7.149875
I20260812 06:18:43.888842 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.033s	user 0.012s	sys 0.018s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":9487,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:18:43.889474 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling UndoDeltaBlockGCOp(ab0da943a7e7425d81ff9cfad8359cd6): 472 bytes on disk
I20260812 06:18:43.890112 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: UndoDeltaBlockGCOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":93,"lbm_reads_lt_1ms":4}
I20260812 06:18:43.890694 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=2.188937
I20260812 06:18:43.900804 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3909,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:43.901214 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=1.000000
I20260812 06:18:44.102681 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.201s	user 0.151s	sys 0.040s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877213,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":421,"lbm_read_time_us":14074,"lbm_reads_lt_1ms":673,"lbm_write_time_us":32761,"lbm_writes_lt_1ms":643,"mutex_wait_us":68,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12672,"thread_start_us":94,"threads_started":1,"update_count":3000}
I20260812 06:18:44.103354 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=14.095187
I20260812 06:18:44.164732 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.061s	user 0.034s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21083,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:44.165313 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=2.188937
I20260812 06:18:44.176980 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4528,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.177495 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=1.000000
I20260812 06:18:44.381232 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.204s	user 0.138s	sys 0.060s 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":856,"lbm_read_time_us":14806,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33972,"lbm_writes_lt_1ms":543,"mutex_wait_us":295,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2500}
I20260812 06:18:44.381872 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=14.095187
I20260812 06:18:44.430147 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.048s	user 0.030s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21189,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:44.430672 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=2.188937
I20260812 06:18:44.451139 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.020s	user 0.004s	sys 0.016s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4461,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.451787 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=1.000000
I20260812 06:18:44.632143 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.180s	user 0.116s	sys 0.062s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":363,"lbm_read_time_us":11549,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32039,"lbm_writes_lt_1ms":543,"mutex_wait_us":45,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15488,"update_count":2500}
I20260812 06:18:44.632800 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=14.095187
I20260812 06:18:44.685554 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.053s	user 0.031s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21864,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:44.686170 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=2.188937
I20260812 06:18:44.697850 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4281,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.698347 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=1.000000
I20260812 06:18:44.867399 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.169s	user 0.107s	sys 0.052s 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":296,"lbm_read_time_us":10225,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26945,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":2500}
I20260812 06:18:44.868000 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=11.118625
I20260812 06:18:44.903594 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.035s	user 0.030s	sys 0.004s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15715,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:44.904160 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=2.188937
I20260812 06:18:44.921460 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.017s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5150,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:44.921979 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=1.000000
I20260812 06:18:45.057943 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.136s	user 0.122s	sys 0.011s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":161,"lbm_read_time_us":8065,"lbm_reads_lt_1ms":464,"lbm_write_time_us":28384,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.058569 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=11.118625
I20260812 06:18:45.093304 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.035s	user 0.019s	sys 0.013s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":15311,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:45.093809 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=2.188937
I20260812 06:18:45.104753 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3878,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:45.105259 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=1.000000
I20260812 06:18:45.232208 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.127s	user 0.094s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672270,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1518,"lbm_read_time_us":9251,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24349,"lbm_writes_lt_1ms":443,"mutex_wait_us":432,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:18:45.232805 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=10.126437
I20260812 06:18:45.285117 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.052s	user 0.029s	sys 0.018s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18014,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:45.285746 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=2.188937
I20260812 06:18:45.296762 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4289,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.297405 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushMRSOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=1.000000
I20260812 06:18:45.344165 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushMRSOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.047s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":81,"dirs.run_cpu_time_us":234,"dirs.run_wall_time_us":1208,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1656,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:45.344942 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling LogGCOp(ab0da943a7e7425d81ff9cfad8359cd6): free 120100328 bytes of WAL
I20260812 06:18:45.345180 24454 log_reader.cc:385] T ab0da943a7e7425d81ff9cfad8359cd6: removed 12 log segments from log reader
I20260812 06:18:45.345225 24454 log.cc:1079] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/ab0da943a7e7425d81ff9cfad8359cd6/wal-000000015 (ops 70-74)
I20260812 06:18:45.345274 24454 log.cc:1079] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/ab0da943a7e7425d81ff9cfad8359cd6/wal-000000016 (ops 75-79)
I20260812 06:18:45.345319 24454 log.cc:1079] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/ab0da943a7e7425d81ff9cfad8359cd6/wal-000000017 (ops 80-84)
I20260812 06:18:45.345376 24454 log.cc:1079] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/ab0da943a7e7425d81ff9cfad8359cd6/wal-000000018 (ops 85-88)
I20260812 06:18:45.345419 24454 log.cc:1079] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/ab0da943a7e7425d81ff9cfad8359cd6/wal-000000019 (ops 89-93)
I20260812 06:18:45.345458 24454 log.cc:1079] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/ab0da943a7e7425d81ff9cfad8359cd6/wal-000000020 (ops 94-98)
I20260812 06:18:45.345495 24454 log.cc:1079] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/ab0da943a7e7425d81ff9cfad8359cd6/wal-000000021 (ops 99-102)
I20260812 06:18:45.345533 24454 log.cc:1079] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/ab0da943a7e7425d81ff9cfad8359cd6/wal-000000022 (ops 103-107)
I20260812 06:18:45.345571 24454 log.cc:1079] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/ab0da943a7e7425d81ff9cfad8359cd6/wal-000000023 (ops 108-112)
I20260812 06:18:45.345609 24454 log.cc:1079] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/ab0da943a7e7425d81ff9cfad8359cd6/wal-000000024 (ops 113-116)
I20260812 06:18:45.345649 24454 log.cc:1079] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/ab0da943a7e7425d81ff9cfad8359cd6/wal-000000025 (ops 117-121)
I20260812 06:18:45.345692 24454 log.cc:1079] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/ab0da943a7e7425d81ff9cfad8359cd6/wal-000000026 (ops 122-126)
I20260812 06:18:45.373761 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: LogGCOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.029s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:45.374290 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling UndoDeltaBlockGCOp(ab0da943a7e7425d81ff9cfad8359cd6): 463 bytes on disk
I20260812 06:18:45.374899 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: UndoDeltaBlockGCOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:18:45.375473 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=3.181125
I20260812 06:18:45.388460 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.013s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4649,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:45.388955 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=2.188937
I20260812 06:18:45.398849 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3613,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:45.399329 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=1.000000
I20260812 06:18:45.607496 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.208s	user 0.133s	sys 0.073s 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":3260,"lbm_read_time_us":14801,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35709,"lbm_writes_lt_1ms":643,"mutex_wait_us":2524,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":87,"threads_started":1,"update_count":3000}
I20260812 06:18:45.608398 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=14.095187
I20260812 06:18:45.672338 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.064s	user 0.035s	sys 0.013s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":22290,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.672931 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=2.188937
I20260812 06:18:45.684933 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.012s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4162,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.685460 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=1.000000
I20260812 06:18:45.851656 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.166s	user 0.086s	sys 0.080s 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":242,"lbm_read_time_us":10504,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30626,"lbm_writes_lt_1ms":543,"mutex_wait_us":71,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:45.852277 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=14.095187
I20260812 06:18:45.907130 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.055s	user 0.027s	sys 0.027s Metrics: {"bytes_written":16409911,"delete_count":0,"lbm_write_time_us":20144,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.907701 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=2.188937
I20260812 06:18:45.918596 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4367,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.919031 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=1.000000
I20260812 06:18:46.085551 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.166s	user 0.126s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774697,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":377,"lbm_read_time_us":13687,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29386,"lbm_writes_lt_1ms":543,"mutex_wait_us":62,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2500}
I20260812 06:18:46.086380 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=10.126437
I20260812 06:18:46.134557 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.048s	user 0.023s	sys 0.024s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":20697,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:46.135068 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=2.188937
I20260812 06:18:46.155478 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.020s	user 0.008s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4181,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.156190 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=1.000000
I20260812 06:18:46.299398 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.143s	user 0.086s	sys 0.056s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672280,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":729,"lbm_read_time_us":10725,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22002,"lbm_writes_lt_1ms":443,"mutex_wait_us":57,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2000}
I20260812 06:18:46.300096 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=10.126437
I20260812 06:18:46.341400 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.041s	user 0.030s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15525,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:46.342089 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=2.188937
I20260812 06:18:46.355492 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4694,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.356057 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=1.000000
I20260812 06:18:46.489602 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.133s	user 0.117s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":481,"lbm_read_time_us":10389,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25739,"lbm_writes_lt_1ms":443,"mutex_wait_us":290,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":2000}
I20260812 06:18:46.490430 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=10.126437
I20260812 06:18:46.523795 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.033s	user 0.027s	sys 0.004s Metrics: {"bytes_written":12471587,"delete_count":0,"lbm_write_time_us":14317,"lbm_writes_lt_1ms":307,"reinsert_count":0,"update_count":1520}
I20260812 06:18:46.524420 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=2.188937
I20260812 06:18:46.536805 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":3938559,"delete_count":0,"lbm_write_time_us":4771,"lbm_writes_lt_1ms":99,"reinsert_count":0,"update_count":480}
I20260812 06:18:46.537256 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=1.000000
I20260812 06:18:46.665169 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.128s	user 0.092s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672274,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":330,"lbm_read_time_us":9637,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25119,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:18:46.665931 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=10.126437
I20260812 06:18:46.713908 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.048s	user 0.021s	sys 0.019s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14149,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:46.714532 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=2.188937
I20260812 06:18:46.725625 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4274,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.726090 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushMRSOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=1.000000
I20260812 06:18:46.772078 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushMRSOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.046s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":46,"dirs.run_cpu_time_us":179,"dirs.run_wall_time_us":1121,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2131,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:46.772830 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling LogGCOp(ab0da943a7e7425d81ff9cfad8359cd6): free 121006640 bytes of WAL
I20260812 06:18:46.773054 24454 log_reader.cc:385] T ab0da943a7e7425d81ff9cfad8359cd6: removed 12 log segments from log reader
I20260812 06:18:46.773099 24454 log.cc:1079] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/ab0da943a7e7425d81ff9cfad8359cd6/wal-000000027 (ops 127-131)
I20260812 06:18:46.773129 24454 log.cc:1079] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/ab0da943a7e7425d81ff9cfad8359cd6/wal-000000028 (ops 132-136)
I20260812 06:18:46.773257 24454 log.cc:1079] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/ab0da943a7e7425d81ff9cfad8359cd6/wal-000000029 (ops 137-141)
I20260812 06:18:46.773306 24454 log.cc:1079] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/ab0da943a7e7425d81ff9cfad8359cd6/wal-000000030 (ops 142-146)
I20260812 06:18:46.773353 24454 log.cc:1079] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/ab0da943a7e7425d81ff9cfad8359cd6/wal-000000031 (ops 147-151)
I20260812 06:18:46.773394 24454 log.cc:1079] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/ab0da943a7e7425d81ff9cfad8359cd6/wal-000000032 (ops 152-156)
I20260812 06:18:46.773434 24454 log.cc:1079] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/ab0da943a7e7425d81ff9cfad8359cd6/wal-000000033 (ops 157-161)
I20260812 06:18:46.773475 24454 log.cc:1079] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/ab0da943a7e7425d81ff9cfad8359cd6/wal-000000034 (ops 162-166)
I20260812 06:18:46.773514 24454 log.cc:1079] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/ab0da943a7e7425d81ff9cfad8359cd6/wal-000000035 (ops 167-171)
I20260812 06:18:46.773551 24454 log.cc:1079] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/ab0da943a7e7425d81ff9cfad8359cd6/wal-000000036 (ops 172-176)
I20260812 06:18:46.773589 24454 log.cc:1079] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/ab0da943a7e7425d81ff9cfad8359cd6/wal-000000037 (ops 177-180)
I20260812 06:18:46.773627 24454 log.cc:1079] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/ab0da943a7e7425d81ff9cfad8359cd6/wal-000000038 (ops 181-185)
I20260812 06:18:46.801522 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: LogGCOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.029s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:46.801923 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=3.181125
I20260812 06:18:46.815999 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.014s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4334,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:46.816488 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=2.188937
I20260812 06:18:46.825940 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3592,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:46.826581 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=1.000000
I20260812 06:18:47.024987 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.198s	user 0.137s	sys 0.061s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877327,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":570,"lbm_read_time_us":14576,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31244,"lbm_writes_lt_1ms":643,"mutex_wait_us":83,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4736,"thread_start_us":79,"threads_started":1,"update_count":3000}
I20260812 06:18:47.025803 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=14.095187
I20260812 06:18:47.078716 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.053s	user 0.035s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22522,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:47.079198 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling UndoDeltaBlockGCOp(ab0da943a7e7425d81ff9cfad8359cd6): 447 bytes on disk
I20260812 06:18:47.079711 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: UndoDeltaBlockGCOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:18:47.080281 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=1.000000
I20260812 06:18:47.191016 24294 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.034s	user 1.824s	sys 0.166s
I20260812 06:18:47.213704 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.133s	user 0.080s	sys 0.051s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"lbm_read_time_us":9436,"lbm_reads_lt_1ms":459,"lbm_write_time_us":22736,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:47.214172 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=10.126437
I20260812 06:18:47.244849 24294 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.053s	user 0.003s	sys 0.000s
I20260812 06:18:47.246148 24294 tablet_server.cc:179] TabletServer@127.23.185.129:0 shutting down...
I20260812 06:18:47.247331 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: FlushDeltaMemStoresOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.033s	user 0.021s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13953,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:47.247792 24556 maintenance_manager.cc:419] P 25e2ac2d5c5a4040a0189d4f4eb12f26: Scheduling MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6): perf score=1.000000
I20260812 06:18:47.343240 24454 maintenance_manager.cc:643] P 25e2ac2d5c5a4040a0189d4f4eb12f26: MajorDeltaCompactionOp(ab0da943a7e7425d81ff9cfad8359cd6) complete. Timing: real 0.095s	user 0.071s	sys 0.024s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569747,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":436,"lbm_read_time_us":7540,"lbm_reads_lt_1ms":367,"lbm_write_time_us":16985,"lbm_writes_lt_1ms":343,"mutex_wait_us":29,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":17664,"update_count":1500}
I20260812 06:18:47.344077 24294 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:47.344666 24294 tablet_replica.cc:333] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26: stopping tablet replica
I20260812 06:18:47.344941 24294 raft_consensus.cc:2243] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:47.345203 24294 raft_consensus.cc:2272] T ab0da943a7e7425d81ff9cfad8359cd6 P 25e2ac2d5c5a4040a0189d4f4eb12f26 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:47.360709 24294 tablet_server.cc:196] TabletServer@127.23.185.129:0 shutdown complete.
I20260812 06:18:47.375777 24294 master.cc:562] Master@127.23.185.190:44015 shutting down...
I20260812 06:18:47.379561 24294 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 8f08deb65b8e4a7994f53470a102d675 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:47.379731 24294 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 8f08deb65b8e4a7994f53470a102d675 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:47.379801 24294 tablet_replica.cc:333] T 00000000000000000000000000000000 P 8f08deb65b8e4a7994f53470a102d675: stopping tablet replica
I20260812 06:18:47.392046 24294 master.cc:584] Master@127.23.185.190:44015 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5576 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:47.486086 24294 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.23.185.190:40215
I20260812 06:18:47.486507 24294 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:18:47.488574 24294 server_base.cc:1061] running on GCE node
W20260812 06:18:47.488665 24603 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:47.488600 24607 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:47.488701 24605 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:47.489025 24294 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:47.489084 24294 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:47.489108 24294 hybrid_clock.cc:648] HybridClock initialized: now 1786515527489107 us; error 0 us; skew 500 ppm
I20260812 06:18:47.489897 24294 webserver.cc:533] Webserver started at http://127.23.185.190:41129/ using document root <none> and password file <none>
I20260812 06:18:47.490068 24294 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:47.490134 24294 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:47.490211 24294 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:47.490694 24294 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/master-0-root/instance:
uuid: "aae5cbf90ff9462e8d4e4a18dddfa342"
format_stamp: "Formatted at 2026-08-12 06:18:47 on dist-test-slave-68xk"
I20260812 06:18:47.492261 24294 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:47.493269 24613 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:47.493552 24294 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:47.493641 24294 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/master-0-root
uuid: "aae5cbf90ff9462e8d4e4a18dddfa342"
format_stamp: "Formatted at 2026-08-12 06:18:47 on dist-test-slave-68xk"
I20260812 06:18:47.493726 24294 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-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:47.503943 24294 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:47.504307 24294 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:47.508419 24294 rpc_server.cc:307] RPC server started. Bound to: 127.23.185.190:40215
I20260812 06:18:47.511869 24707 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:47.520061 24706 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.185.190:40215 every 8 connection(s)
I20260812 06:18:47.520584 24707 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P aae5cbf90ff9462e8d4e4a18dddfa342: Bootstrap starting.
I20260812 06:18:47.521371 24707 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P aae5cbf90ff9462e8d4e4a18dddfa342: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:47.522480 24707 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P aae5cbf90ff9462e8d4e4a18dddfa342: No bootstrap required, opened a new log
I20260812 06:18:47.522892 24707 raft_consensus.cc:359] T 00000000000000000000000000000000 P aae5cbf90ff9462e8d4e4a18dddfa342 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "aae5cbf90ff9462e8d4e4a18dddfa342" member_type: VOTER }
I20260812 06:18:47.522979 24707 raft_consensus.cc:385] T 00000000000000000000000000000000 P aae5cbf90ff9462e8d4e4a18dddfa342 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:47.523020 24707 raft_consensus.cc:740] T 00000000000000000000000000000000 P aae5cbf90ff9462e8d4e4a18dddfa342 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: aae5cbf90ff9462e8d4e4a18dddfa342, State: Initialized, Role: FOLLOWER
I20260812 06:18:47.523198 24707 consensus_queue.cc:260] T 00000000000000000000000000000000 P aae5cbf90ff9462e8d4e4a18dddfa342 [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: "aae5cbf90ff9462e8d4e4a18dddfa342" member_type: VOTER }
I20260812 06:18:47.523278 24707 raft_consensus.cc:399] T 00000000000000000000000000000000 P aae5cbf90ff9462e8d4e4a18dddfa342 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:47.523343 24707 raft_consensus.cc:493] T 00000000000000000000000000000000 P aae5cbf90ff9462e8d4e4a18dddfa342 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:47.523406 24707 raft_consensus.cc:3060] T 00000000000000000000000000000000 P aae5cbf90ff9462e8d4e4a18dddfa342 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:47.524072 24707 raft_consensus.cc:515] T 00000000000000000000000000000000 P aae5cbf90ff9462e8d4e4a18dddfa342 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "aae5cbf90ff9462e8d4e4a18dddfa342" member_type: VOTER }
I20260812 06:18:47.524216 24707 leader_election.cc:304] T 00000000000000000000000000000000 P aae5cbf90ff9462e8d4e4a18dddfa342 [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: aae5cbf90ff9462e8d4e4a18dddfa342; no voters: 
I20260812 06:18:47.524418 24707 leader_election.cc:290] T 00000000000000000000000000000000 P aae5cbf90ff9462e8d4e4a18dddfa342 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:47.524505 24710 raft_consensus.cc:2804] T 00000000000000000000000000000000 P aae5cbf90ff9462e8d4e4a18dddfa342 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:47.524669 24710 raft_consensus.cc:697] T 00000000000000000000000000000000 P aae5cbf90ff9462e8d4e4a18dddfa342 [term 1 LEADER]: Becoming Leader. State: Replica: aae5cbf90ff9462e8d4e4a18dddfa342, State: Running, Role: LEADER
I20260812 06:18:47.524860 24710 consensus_queue.cc:237] T 00000000000000000000000000000000 P aae5cbf90ff9462e8d4e4a18dddfa342 [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: "aae5cbf90ff9462e8d4e4a18dddfa342" member_type: VOTER }
I20260812 06:18:47.524948 24707 sys_catalog.cc:565] T 00000000000000000000000000000000 P aae5cbf90ff9462e8d4e4a18dddfa342 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:47.525328 24711 sys_catalog.cc:455] T 00000000000000000000000000000000 P aae5cbf90ff9462e8d4e4a18dddfa342 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "aae5cbf90ff9462e8d4e4a18dddfa342" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "aae5cbf90ff9462e8d4e4a18dddfa342" member_type: VOTER } }
I20260812 06:18:47.525354 24713 sys_catalog.cc:455] T 00000000000000000000000000000000 P aae5cbf90ff9462e8d4e4a18dddfa342 [sys.catalog]: SysCatalogTable state changed. Reason: New leader aae5cbf90ff9462e8d4e4a18dddfa342. Latest consensus state: current_term: 1 leader_uuid: "aae5cbf90ff9462e8d4e4a18dddfa342" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "aae5cbf90ff9462e8d4e4a18dddfa342" member_type: VOTER } }
I20260812 06:18:47.525493 24711 sys_catalog.cc:458] T 00000000000000000000000000000000 P aae5cbf90ff9462e8d4e4a18dddfa342 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:47.525509 24713 sys_catalog.cc:458] T 00000000000000000000000000000000 P aae5cbf90ff9462e8d4e4a18dddfa342 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:47.526149 24717 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:47.526952 24717 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:47.527207 24294 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:47.528769 24717 catalog_manager.cc:1383] Generated new cluster ID: 98f6f3e3782f414ea1a91849ff1fe02e
I20260812 06:18:47.528829 24717 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:47.542762 24717 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:47.543284 24717 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:47.551326 24717 catalog_manager.cc:6092] T 00000000000000000000000000000000 P aae5cbf90ff9462e8d4e4a18dddfa342: Generated new TSK 0
I20260812 06:18:47.551468 24717 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:47.559420 24294 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:47.561326 24740 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:47.561429 24294 server_base.cc:1061] running on GCE node
W20260812 06:18:47.561342 24743 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:47.561474 24741 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:47.561757 24294 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:47.561802 24294 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:47.561817 24294 hybrid_clock.cc:648] HybridClock initialized: now 1786515527561818 us; error 0 us; skew 500 ppm
I20260812 06:18:47.562688 24294 webserver.cc:533] Webserver started at http://127.23.185.129:39705/ using document root <none> and password file <none>
I20260812 06:18:47.562824 24294 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:47.562866 24294 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:47.562917 24294 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:47.563262 24294 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root/instance:
uuid: "14d36993acdc42e897d56e2e93b6e409"
format_stamp: "Formatted at 2026-08-12 06:18:47 on dist-test-slave-68xk"
I20260812 06:18:47.564651 24294 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:47.565487 24753 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:47.565732 24294 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:47.565842 24294 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root
uuid: "14d36993acdc42e897d56e2e93b6e409"
format_stamp: "Formatted at 2026-08-12 06:18:47 on dist-test-slave-68xk"
I20260812 06:18:47.565975 24294 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-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:47.571623 24294 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:47.571955 24294 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:47.572235 24294 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:47.572674 24294 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:47.572731 24294 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:47.572788 24294 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:47.572820 24294 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:47.577158 24294 rpc_server.cc:307] RPC server started. Bound to: 127.23.185.129:32813
I20260812 06:18:47.578269 24854 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.23.185.129:32813 every 8 connection(s)
I20260812 06:18:47.588768 24856 heartbeater.cc:344] Connected to a master server at 127.23.185.190:40215
I20260812 06:18:47.588883 24856 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:47.589082 24856 heartbeater.cc:507] Master 127.23.185.190:40215 requested a full tablet report, sending...
I20260812 06:18:47.589718 24640 ts_manager.cc:194] Registered new tserver with Master: 14d36993acdc42e897d56e2e93b6e409 (127.23.185.129:32813)
I20260812 06:18:47.590068 24294 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012224499s
I20260812 06:18:47.590554 24640 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:41300
I20260812 06:18:47.597262 24640 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:41308:
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:47.606293 24801 tablet_service.cc:1511] Processing CreateTablet for tablet 27ae0c06b81f4f6890594eb59469e7b2 (DEFAULT_TABLE table=heavy-update-compaction-test [id=16f5c35731b54996b4d9035754c3aa40]), partition=
I20260812 06:18:47.606616 24801 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 27ae0c06b81f4f6890594eb59469e7b2. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:47.608695 24875 tablet_bootstrap.cc:492] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Bootstrap starting.
I20260812 06:18:47.609560 24875 tablet_bootstrap.cc:654] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:47.610644 24875 tablet_bootstrap.cc:492] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: No bootstrap required, opened a new log
I20260812 06:18:47.610759 24875 ts_tablet_manager.cc:1403] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:47.611155 24875 raft_consensus.cc:359] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "14d36993acdc42e897d56e2e93b6e409" member_type: VOTER last_known_addr { host: "127.23.185.129" port: 32813 } }
I20260812 06:18:47.611265 24875 raft_consensus.cc:385] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:47.611311 24875 raft_consensus.cc:740] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 14d36993acdc42e897d56e2e93b6e409, State: Initialized, Role: FOLLOWER
I20260812 06:18:47.611521 24875 consensus_queue.cc:260] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409 [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: "14d36993acdc42e897d56e2e93b6e409" member_type: VOTER last_known_addr { host: "127.23.185.129" port: 32813 } }
I20260812 06:18:47.611617 24875 raft_consensus.cc:399] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:47.611667 24875 raft_consensus.cc:493] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:47.611726 24875 raft_consensus.cc:3060] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:47.612697 24875 raft_consensus.cc:515] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "14d36993acdc42e897d56e2e93b6e409" member_type: VOTER last_known_addr { host: "127.23.185.129" port: 32813 } }
I20260812 06:18:47.612857 24875 leader_election.cc:304] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409 [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: 14d36993acdc42e897d56e2e93b6e409; no voters: 
I20260812 06:18:47.613062 24875 leader_election.cc:290] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:47.613209 24877 raft_consensus.cc:2804] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:47.613380 24875 ts_tablet_manager.cc:1434] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:47.613467 24877 raft_consensus.cc:697] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409 [term 1 LEADER]: Becoming Leader. State: Replica: 14d36993acdc42e897d56e2e93b6e409, State: Running, Role: LEADER
I20260812 06:18:47.613570 24856 heartbeater.cc:499] Master 127.23.185.190:40215 was elected leader, sending a full tablet report...
I20260812 06:18:47.613771 24877 consensus_queue.cc:237] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409 [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: "14d36993acdc42e897d56e2e93b6e409" member_type: VOTER last_known_addr { host: "127.23.185.129" port: 32813 } }
I20260812 06:18:47.615247 24640 catalog_manager.cc:5719] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409 reported cstate change: term changed from 0 to 1, leader changed from <none> to 14d36993acdc42e897d56e2e93b6e409 (127.23.185.129). New cstate: current_term: 1 leader_uuid: "14d36993acdc42e897d56e2e93b6e409" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "14d36993acdc42e897d56e2e93b6e409" member_type: VOTER last_known_addr { host: "127.23.185.129" port: 32813 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:47.673846 24294 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.051s	user 0.015s	sys 0.006s
I20260812 06:18:47.828781 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushMRSOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=19.054940
I20260812 06:18:48.003365 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushMRSOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.174s	user 0.113s	sys 0.056s Metrics: {"bytes_written":13210025,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":188,"dirs.run_wall_time_us":779,"drs_written":1,"lbm_read_time_us":84,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43994,"lbm_writes_lt_1ms":779,"mutex_wait_us":1035,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1610}
I20260812 06:18:48.004009 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling LogGCOp(27ae0c06b81f4f6890594eb59469e7b2): free 20743880 bytes of WAL
I20260812 06:18:48.004304 24764 log_reader.cc:385] T 27ae0c06b81f4f6890594eb59469e7b2: removed 2 log segments from log reader
I20260812 06:18:48.004376 24764 log.cc:1079] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/27ae0c06b81f4f6890594eb59469e7b2/wal-000000001 (ops 1-6)
I20260812 06:18:48.004426 24764 log.cc:1079] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/27ae0c06b81f4f6890594eb59469e7b2/wal-000000002 (ops 7-11)
I20260812 06:18:48.010144 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: LogGCOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.006s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:48.010561 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling UndoDeltaBlockGCOp(27ae0c06b81f4f6890594eb59469e7b2): 16411392 bytes on disk
I20260812 06:18:48.010993 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: UndoDeltaBlockGCOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:18:48.011387 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=2.188937
I20260812 06:18:48.021692 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3774463,"delete_count":0,"lbm_write_time_us":3664,"lbm_writes_lt_1ms":95,"reinsert_count":0,"update_count":460}
I20260812 06:18:48.022097 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=2.188937
I20260812 06:18:48.032058 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3528305,"delete_count":0,"lbm_write_time_us":3564,"lbm_writes_lt_1ms":89,"reinsert_count":0,"update_count":430}
I20260812 06:18:48.032437 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling MajorDeltaCompactionOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=1.000000
I20260812 06:18:48.216219 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: MajorDeltaCompactionOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.184s	user 0.120s	sys 0.053s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774793,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":549,"lbm_read_time_us":12278,"lbm_reads_lt_1ms":569,"lbm_write_time_us":31136,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"thread_start_us":336,"threads_started":5,"update_count":2500}
I20260812 06:18:48.216843 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=14.095187
I20260812 06:18:48.274236 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.057s	user 0.034s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25124,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2000}
I20260812 06:18:48.274776 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=2.188937
I20260812 06:18:48.287336 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4446,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.287981 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling MajorDeltaCompactionOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=1.000000
I20260812 06:18:48.484127 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: MajorDeltaCompactionOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.196s	user 0.150s	sys 0.043s 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":322,"lbm_read_time_us":14070,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31133,"lbm_writes_lt_1ms":543,"mutex_wait_us":63,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":2500}
I20260812 06:18:48.484786 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=14.095187
I20260812 06:18:48.541800 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.057s	user 0.024s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23565,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:48.542303 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling MajorDeltaCompactionOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=1.000000
I20260812 06:18:48.689458 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: MajorDeltaCompactionOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.147s	user 0.110s	sys 0.033s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1094,"lbm_read_time_us":10321,"lbm_reads_lt_1ms":463,"lbm_write_time_us":23765,"lbm_writes_lt_1ms":443,"mutex_wait_us":361,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2000}
I20260812 06:18:48.690074 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=14.095187
I20260812 06:18:48.740471 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.050s	user 0.029s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19272,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:48.740969 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=2.188937
I20260812 06:18:48.753302 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4603,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.753751 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling MajorDeltaCompactionOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=1.000000
I20260812 06:18:48.948276 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: MajorDeltaCompactionOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.194s	user 0.094s	sys 0.092s 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":659,"lbm_read_time_us":10910,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31305,"lbm_writes_lt_1ms":543,"mutex_wait_us":294,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":29568,"update_count":2500}
I20260812 06:18:48.948997 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=14.095187
I20260812 06:18:48.997231 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.048s	user 0.024s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19315,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:48.997820 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=2.188937
I20260812 06:18:49.010821 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.013s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4936,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.011957 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling MajorDeltaCompactionOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=1.000000
I20260812 06:18:49.179181 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: MajorDeltaCompactionOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.167s	user 0.135s	sys 0.024s 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":395,"lbm_read_time_us":9300,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31150,"lbm_writes_lt_1ms":543,"mutex_wait_us":55,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":2500}
I20260812 06:18:49.179780 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=14.095187
I20260812 06:18:49.232432 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.052s	user 0.026s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23103,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:49.233036 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=2.188937
I20260812 06:18:49.245710 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.012s	user 0.007s	sys 0.004s 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:49.246223 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushMRSOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=1.000000
I20260812 06:18:49.278147 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushMRSOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.032s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":225,"dirs.run_wall_time_us":1438,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1830,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:49.278825 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling LogGCOp(27ae0c06b81f4f6890594eb59469e7b2): free 120553343 bytes of WAL
I20260812 06:18:49.279104 24764 log_reader.cc:385] T 27ae0c06b81f4f6890594eb59469e7b2: removed 12 log segments from log reader
I20260812 06:18:49.279170 24764 log.cc:1079] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/27ae0c06b81f4f6890594eb59469e7b2/wal-000000003 (ops 12-16)
I20260812 06:18:49.279211 24764 log.cc:1079] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/27ae0c06b81f4f6890594eb59469e7b2/wal-000000004 (ops 17-21)
I20260812 06:18:49.279235 24764 log.cc:1079] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/27ae0c06b81f4f6890594eb59469e7b2/wal-000000005 (ops 22-26)
I20260812 06:18:49.279261 24764 log.cc:1079] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/27ae0c06b81f4f6890594eb59469e7b2/wal-000000006 (ops 27-30)
I20260812 06:18:49.279287 24764 log.cc:1079] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/27ae0c06b81f4f6890594eb59469e7b2/wal-000000007 (ops 31-35)
I20260812 06:18:49.279311 24764 log.cc:1079] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/27ae0c06b81f4f6890594eb59469e7b2/wal-000000008 (ops 36-40)
I20260812 06:18:49.279335 24764 log.cc:1079] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/27ae0c06b81f4f6890594eb59469e7b2/wal-000000009 (ops 41-44)
I20260812 06:18:49.279357 24764 log.cc:1079] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/27ae0c06b81f4f6890594eb59469e7b2/wal-000000010 (ops 45-49)
I20260812 06:18:49.279381 24764 log.cc:1079] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/27ae0c06b81f4f6890594eb59469e7b2/wal-000000011 (ops 50-54)
I20260812 06:18:49.279402 24764 log.cc:1079] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/27ae0c06b81f4f6890594eb59469e7b2/wal-000000012 (ops 55-59)
I20260812 06:18:49.279426 24764 log.cc:1079] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/27ae0c06b81f4f6890594eb59469e7b2/wal-000000013 (ops 60-64)
I20260812 06:18:49.279453 24764 log.cc:1079] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/27ae0c06b81f4f6890594eb59469e7b2/wal-000000014 (ops 65-69)
I20260812 06:18:49.309345 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: LogGCOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.030s	user 0.001s	sys 0.027s Metrics: {}
I20260812 06:18:49.309787 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling UndoDeltaBlockGCOp(27ae0c06b81f4f6890594eb59469e7b2): 463 bytes on disk
I20260812 06:18:49.310453 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: UndoDeltaBlockGCOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:18:49.311044 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=3.181125
I20260812 06:18:49.336447 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.025s	user 0.004s	sys 0.019s Metrics: {"bytes_written":5128263,"delete_count":0,"lbm_write_time_us":5283,"lbm_writes_lt_1ms":128,"reinsert_count":0,"update_count":625}
I20260812 06:18:49.336997 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=1.196750
I20260812 06:18:49.350889 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.014s	user 0.002s	sys 0.011s Metrics: {"bytes_written":3077030,"delete_count":0,"lbm_write_time_us":4854,"lbm_writes_lt_1ms":78,"reinsert_count":0,"update_count":375}
I20260812 06:18:49.351509 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling MajorDeltaCompactionOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=1.000000
I20260812 06:18:49.568658 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: MajorDeltaCompactionOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.217s	user 0.148s	sys 0.068s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979725,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":656,"lbm_read_time_us":15196,"lbm_reads_lt_1ms":774,"lbm_write_time_us":37677,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":117,"threads_started":1,"update_count":3500}
I20260812 06:18:49.569270 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=14.095187
I20260812 06:18:49.630777 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.061s	user 0.044s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26635,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:49.631402 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=2.188937
I20260812 06:18:49.650915 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.019s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4511,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.651470 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling MajorDeltaCompactionOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=1.000000
I20260812 06:18:49.828786 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: MajorDeltaCompactionOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.177s	user 0.130s	sys 0.047s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":500,"lbm_read_time_us":12448,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29632,"lbm_writes_lt_1ms":543,"mutex_wait_us":92,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":2500}
I20260812 06:18:49.829452 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=14.095187
I20260812 06:18:49.895576 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.066s	user 0.042s	sys 0.023s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":24634,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:49.896204 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=2.188937
I20260812 06:18:49.907258 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4130,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.907729 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling MajorDeltaCompactionOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=1.000000
I20260812 06:18:50.074834 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: MajorDeltaCompactionOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.167s	user 0.095s	sys 0.071s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":117,"lbm_read_time_us":12545,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27779,"lbm_writes_lt_1ms":543,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5120,"update_count":2500}
I20260812 06:18:50.075446 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=10.126437
I20260812 06:18:50.126523 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.050s	user 0.024s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":22019,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:50.127240 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=2.188937
I20260812 06:18:50.145051 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.018s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5323,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.145807 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling MajorDeltaCompactionOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=1.000000
I20260812 06:18:50.278535 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: MajorDeltaCompactionOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.133s	user 0.103s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":666,"lbm_read_time_us":7948,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25375,"lbm_writes_lt_1ms":443,"mutex_wait_us":80,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2000}
I20260812 06:18:50.279323 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=10.126437
I20260812 06:18:50.317561 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.038s	user 0.017s	sys 0.018s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15579,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:50.318091 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=2.188937
I20260812 06:18:50.334944 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.017s	user 0.013s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6571,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.335440 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling MajorDeltaCompactionOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=1.000000
I20260812 06:18:50.465510 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: MajorDeltaCompactionOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.130s	user 0.101s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":342,"lbm_read_time_us":8885,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25930,"lbm_writes_lt_1ms":443,"mutex_wait_us":71,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:50.466370 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=10.126437
I20260812 06:18:50.504366 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.037s	user 0.009s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14554,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:50.504951 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=2.188937
I20260812 06:18:50.518164 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.013s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5125,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.518697 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling MajorDeltaCompactionOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=1.000000
I20260812 06:18:50.646574 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: MajorDeltaCompactionOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.128s	user 0.098s	sys 0.029s 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":921,"lbm_read_time_us":9832,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25769,"lbm_writes_lt_1ms":443,"mutex_wait_us":210,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14976,"update_count":2000}
I20260812 06:18:50.647310 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=10.126437
I20260812 06:18:50.700706 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.053s	user 0.022s	sys 0.029s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17221,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:50.701354 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=2.188937
I20260812 06:18:50.717885 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6002,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.718375 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushMRSOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=1.000000
I20260812 06:18:50.742637 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushMRSOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.024s	user 0.019s	sys 0.005s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":216,"dirs.run_wall_time_us":1450,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1462,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:50.743294 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling LogGCOp(27ae0c06b81f4f6890594eb59469e7b2): free 111786323 bytes of WAL
I20260812 06:18:50.743515 24764 log_reader.cc:385] T 27ae0c06b81f4f6890594eb59469e7b2: removed 11 log segments from log reader
I20260812 06:18:50.743561 24764 log.cc:1079] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/27ae0c06b81f4f6890594eb59469e7b2/wal-000000015 (ops 70-74)
I20260812 06:18:50.743605 24764 log.cc:1079] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/27ae0c06b81f4f6890594eb59469e7b2/wal-000000016 (ops 75-79)
I20260812 06:18:50.743652 24764 log.cc:1079] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/27ae0c06b81f4f6890594eb59469e7b2/wal-000000017 (ops 80-84)
I20260812 06:18:50.743695 24764 log.cc:1079] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/27ae0c06b81f4f6890594eb59469e7b2/wal-000000018 (ops 85-88)
I20260812 06:18:50.743745 24764 log.cc:1079] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/27ae0c06b81f4f6890594eb59469e7b2/wal-000000019 (ops 89-93)
I20260812 06:18:50.743804 24764 log.cc:1079] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/27ae0c06b81f4f6890594eb59469e7b2/wal-000000020 (ops 94-98)
I20260812 06:18:50.743845 24764 log.cc:1079] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/27ae0c06b81f4f6890594eb59469e7b2/wal-000000021 (ops 99-103)
I20260812 06:18:50.743884 24764 log.cc:1079] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/27ae0c06b81f4f6890594eb59469e7b2/wal-000000022 (ops 104-108)
I20260812 06:18:50.743947 24764 log.cc:1079] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/27ae0c06b81f4f6890594eb59469e7b2/wal-000000023 (ops 109-112)
I20260812 06:18:50.744001 24764 log.cc:1079] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/27ae0c06b81f4f6890594eb59469e7b2/wal-000000024 (ops 113-117)
I20260812 06:18:50.744046 24764 log.cc:1079] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/27ae0c06b81f4f6890594eb59469e7b2/wal-000000025 (ops 118-122)
I20260812 06:18:50.770435 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: LogGCOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.027s	user 0.004s	sys 0.019s Metrics: {}
I20260812 06:18:50.770874 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling UndoDeltaBlockGCOp(27ae0c06b81f4f6890594eb59469e7b2): 461 bytes on disk
I20260812 06:18:50.771298 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: UndoDeltaBlockGCOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:18:50.771816 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=3.181125
I20260812 06:18:50.784495 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.013s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4512904,"delete_count":0,"lbm_write_time_us":4492,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:50.784947 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling LogGCOp(27ae0c06b81f4f6890594eb59469e7b2): free 8767116 bytes of WAL
I20260812 06:18:50.785193 24764 log_reader.cc:385] T 27ae0c06b81f4f6890594eb59469e7b2: removed 1 log segments from log reader
I20260812 06:18:50.785266 24764 log.cc:1079] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/27ae0c06b81f4f6890594eb59469e7b2/wal-000000026 (ops 123-127)
I20260812 06:18:50.787132 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: LogGCOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.002s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:50.787402 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=2.188937
I20260812 06:18:50.797247 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.010s	user 0.003s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3643,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:50.797768 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling MajorDeltaCompactionOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=1.000000
I20260812 06:18:51.025950 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: MajorDeltaCompactionOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.228s	user 0.156s	sys 0.072s 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":253,"lbm_read_time_us":14924,"lbm_reads_lt_1ms":674,"lbm_write_time_us":38355,"lbm_writes_lt_1ms":643,"mutex_wait_us":28,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":30976,"thread_start_us":104,"threads_started":1,"update_count":3000}
I20260812 06:18:51.029007 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=15.087375
I20260812 06:18:51.076428 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.047s	user 0.023s	sys 0.022s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":23333,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":412,"reinsert_count":0,"update_count":2050}
I20260812 06:18:51.077051 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=2.188937
I20260812 06:18:51.100030 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.023s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3753,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:51.100482 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=2.188937
I20260812 06:18:51.111613 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4213,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:51.112408 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling MajorDeltaCompactionOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=1.000000
I20260812 06:18:51.340133 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: MajorDeltaCompactionOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.227s	user 0.145s	sys 0.081s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877206,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":334,"lbm_read_time_us":15331,"lbm_reads_lt_1ms":673,"lbm_write_time_us":38905,"lbm_writes_lt_1ms":643,"mutex_wait_us":37,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":17536,"update_count":3000}
I20260812 06:18:51.342991 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=16.079562
I20260812 06:18:51.416839 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.074s	user 0.020s	sys 0.041s Metrics: {"bytes_written":17681653,"delete_count":0,"lbm_write_time_us":30154,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":433,"reinsert_count":0,"update_count":2155}
I20260812 06:18:51.417330 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=5.165500
I20260812 06:18:51.435632 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.018s	user 0.005s	sys 0.012s Metrics: {"bytes_written":6933336,"delete_count":0,"lbm_write_time_us":7079,"lbm_writes_lt_1ms":172,"reinsert_count":0,"update_count":845}
I20260812 06:18:51.436157 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling MajorDeltaCompactionOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=1.000000
I20260812 06:18:51.651279 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: MajorDeltaCompactionOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.215s	user 0.135s	sys 0.079s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877111,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1150,"lbm_read_time_us":15197,"lbm_reads_lt_1ms":672,"lbm_write_time_us":37661,"lbm_writes_lt_1ms":643,"mutex_wait_us":466,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":3000}
I20260812 06:18:51.652499 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=16.079562
I20260812 06:18:51.711436 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.059s	user 0.040s	sys 0.016s Metrics: {"bytes_written":17681651,"delete_count":0,"lbm_write_time_us":25421,"lbm_writes_lt_1ms":434,"reinsert_count":0,"update_count":2155}
I20260812 06:18:51.712059 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=2.188937
I20260812 06:18:51.732784 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.020s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3241134,"delete_count":0,"lbm_write_time_us":5102,"lbm_writes_lt_1ms":82,"reinsert_count":0,"update_count":395}
I20260812 06:18:51.733283 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=2.188937
I20260812 06:18:51.747829 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5616,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:51.748358 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling MajorDeltaCompactionOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=1.000000
I20260812 06:18:51.965451 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: MajorDeltaCompactionOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.217s	user 0.127s	sys 0.087s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877190,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":352,"lbm_read_time_us":15071,"lbm_reads_lt_1ms":673,"lbm_write_time_us":38129,"lbm_writes_lt_1ms":643,"mutex_wait_us":63,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":3000}
I20260812 06:18:51.966260 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=15.087375
I20260812 06:18:52.021875 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.055s	user 0.036s	sys 0.016s Metrics: {"bytes_written":17312435,"delete_count":0,"lbm_write_time_us":24559,"lbm_writes_lt_1ms":425,"reinsert_count":0,"update_count":2110}
I20260812 06:18:52.022454 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=2.188937
I20260812 06:18:52.042289 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.020s	user 0.009s	sys 0.001s Metrics: {"bytes_written":3200105,"delete_count":0,"lbm_write_time_us":4636,"lbm_writes_lt_1ms":81,"reinsert_count":0,"update_count":390}
I20260812 06:18:52.042773 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=2.188937
I20260812 06:18:52.052784 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.010s	user 0.003s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4045,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:52.053188 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling MajorDeltaCompactionOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=1.000000
I20260812 06:18:52.252370 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: MajorDeltaCompactionOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.199s	user 0.155s	sys 0.043s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877199,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":283,"lbm_read_time_us":14528,"lbm_reads_lt_1ms":673,"lbm_write_time_us":32448,"lbm_writes_lt_1ms":643,"mutex_wait_us":23,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8320,"update_count":3000}
I20260812 06:18:52.253237 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=14.095187
I20260812 06:18:52.309219 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.056s	user 0.025s	sys 0.028s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":23859,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2000}
I20260812 06:18:52.309863 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=2.188937
I20260812 06:18:52.327657 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.018s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5212,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:52.328191 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=2.188937
I20260812 06:18:52.340029 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4662,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:52.340507 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushMRSOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=1.000000
I20260812 06:18:52.373286 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushMRSOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.033s	user 0.026s	sys 0.005s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":277,"dirs.run_wall_time_us":1425,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1780,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:52.374063 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling LogGCOp(27ae0c06b81f4f6890594eb59469e7b2): free 124257527 bytes of WAL
I20260812 06:18:52.374351 24764 log_reader.cc:385] T 27ae0c06b81f4f6890594eb59469e7b2: removed 12 log segments from log reader
I20260812 06:18:52.374455 24764 log.cc:1079] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/27ae0c06b81f4f6890594eb59469e7b2/wal-000000027 (ops 128-132)
I20260812 06:18:52.374506 24764 log.cc:1079] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/27ae0c06b81f4f6890594eb59469e7b2/wal-000000028 (ops 133-137)
I20260812 06:18:52.374545 24764 log.cc:1079] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/27ae0c06b81f4f6890594eb59469e7b2/wal-000000029 (ops 138-142)
I20260812 06:18:52.374572 24764 log.cc:1079] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/27ae0c06b81f4f6890594eb59469e7b2/wal-000000030 (ops 143-147)
I20260812 06:18:52.374604 24764 log.cc:1079] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/27ae0c06b81f4f6890594eb59469e7b2/wal-000000031 (ops 148-152)
I20260812 06:18:52.374637 24764 log.cc:1079] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/27ae0c06b81f4f6890594eb59469e7b2/wal-000000032 (ops 153-156)
I20260812 06:18:52.374676 24764 log.cc:1079] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/27ae0c06b81f4f6890594eb59469e7b2/wal-000000033 (ops 157-161)
I20260812 06:18:52.374713 24764 log.cc:1079] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/27ae0c06b81f4f6890594eb59469e7b2/wal-000000034 (ops 162-166)
I20260812 06:18:52.374747 24764 log.cc:1079] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/27ae0c06b81f4f6890594eb59469e7b2/wal-000000035 (ops 167-171)
I20260812 06:18:52.374779 24764 log.cc:1079] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/27ae0c06b81f4f6890594eb59469e7b2/wal-000000036 (ops 172-176)
I20260812 06:18:52.374812 24764 log.cc:1079] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/27ae0c06b81f4f6890594eb59469e7b2/wal-000000037 (ops 177-181)
I20260812 06:18:52.374850 24764 log.cc:1079] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: Deleting log segment in path: /tmp/dist-test-taskhpsLO5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521898751-24294-0/minicluster-data/ts-0-root/wals/27ae0c06b81f4f6890594eb59469e7b2/wal-000000038 (ops 182-186)
I20260812 06:18:52.410552 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: LogGCOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.036s	user 0.001s	sys 0.035s Metrics: {}
I20260812 06:18:52.411072 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=3.181125
I20260812 06:18:52.437652 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.026s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7345,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:52.438180 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=2.188937
I20260812 06:18:52.448422 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3927,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:52.448858 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling UndoDeltaBlockGCOp(27ae0c06b81f4f6890594eb59469e7b2): 483 bytes on disk
I20260812 06:18:52.449499 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: UndoDeltaBlockGCOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":104,"lbm_reads_lt_1ms":4}
I20260812 06:18:52.450591 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling MajorDeltaCompactionOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=1.000000
I20260812 06:18:52.651870 24294 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.978s	user 1.853s	sys 0.192s
I20260812 06:18:52.668320 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: MajorDeltaCompactionOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.218s	user 0.158s	sys 0.057s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37082273,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"lbm_read_time_us":16454,"lbm_reads_lt_1ms":871,"lbm_write_time_us":41029,"lbm_writes_lt_1ms":843,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":4000}
I20260812 06:18:52.668815 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=18.063937
I20260812 06:18:52.708623 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: FlushDeltaMemStoresOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.040s	user 0.018s	sys 0.021s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":19531,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:52.709174 24857 maintenance_manager.cc:419] P 14d36993acdc42e897d56e2e93b6e409: Scheduling MajorDeltaCompactionOp(27ae0c06b81f4f6890594eb59469e7b2): perf score=1.000000
I20260812 06:18:52.730103 24294 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.078s	user 0.002s	sys 0.000s
I20260812 06:18:52.730675 24294 tablet_server.cc:179] TabletServer@127.23.185.129:0 shutting down...
I20260812 06:18:52.837684 24764 maintenance_manager.cc:643] P 14d36993acdc42e897d56e2e93b6e409: MajorDeltaCompactionOp(27ae0c06b81f4f6890594eb59469e7b2) complete. Timing: real 0.128s	user 0.100s	sys 0.028s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24774571,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":889,"lbm_read_time_us":10510,"lbm_reads_lt_1ms":567,"lbm_write_time_us":27565,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":347,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:52.838294 24294 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:52.838536 24294 tablet_replica.cc:333] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409: stopping tablet replica
I20260812 06:18:52.838707 24294 raft_consensus.cc:2243] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:52.838882 24294 raft_consensus.cc:2272] T 27ae0c06b81f4f6890594eb59469e7b2 P 14d36993acdc42e897d56e2e93b6e409 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:52.842140 24294 tablet_server.cc:196] TabletServer@127.23.185.129:0 shutdown complete.
I20260812 06:18:52.888993 24294 master.cc:562] Master@127.23.185.190:40215 shutting down...
I20260812 06:18:52.892472 24294 raft_consensus.cc:2243] T 00000000000000000000000000000000 P aae5cbf90ff9462e8d4e4a18dddfa342 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:52.892681 24294 raft_consensus.cc:2272] T 00000000000000000000000000000000 P aae5cbf90ff9462e8d4e4a18dddfa342 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:52.892764 24294 tablet_replica.cc:333] T 00000000000000000000000000000000 P aae5cbf90ff9462e8d4e4a18dddfa342: stopping tablet replica
I20260812 06:18:52.905125 24294 master.cc:584] Master@127.23.185.190:40215 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5511 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11089 ms total)

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