[==========] 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:20:05.230944 27737 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.27.22.126:39897
I20260812 06:20:05.232029 27737 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:20:05.232784 27737 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:05.239665 27752 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:20:05.239709 27745 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:20:05.239966 27737 server_base.cc:1061] running on GCE node
W20260812 06:20:05.239993 27747 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:20:05.240486 27737 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:05.240622 27737 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:20:05.240681 27737 hybrid_clock.cc:648] HybridClock initialized: now 1786515605240679 us; error 0 us; skew 500 ppm
I20260812 06:20:05.242404 27737 webserver.cc:533] Webserver started at http://127.27.22.126:42649/ using document root <none> and password file <none>
I20260812 06:20:05.242942 27737 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:05.243031 27737 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:05.243324 27737 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:05.244949 27737 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/master-0-root/instance:
uuid: "ad060527d7ec4dfaa4daafa98b558005"
format_stamp: "Formatted at 2026-08-12 06:20:05 on dist-test-slave-92m1"
I20260812 06:20:05.248288 27737 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:20:05.250224 27759 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:20:05.251194 27737 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:05.251371 27737 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/master-0-root
uuid: "ad060527d7ec4dfaa4daafa98b558005"
format_stamp: "Formatted at 2026-08-12 06:20:05 on dist-test-slave-92m1"
I20260812 06:20:05.251469 27737 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-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:20:05.265314 27737 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:05.265931 27737 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:20:05.266115 27737 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:05.273950 27737 rpc_server.cc:307] RPC server started. Bound to: 127.27.22.126:39897
I20260812 06:20:05.273958 27862 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.22.126:39897 every 8 connection(s)
I20260812 06:20:05.276105 27863 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:20:05.281164 27863 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ad060527d7ec4dfaa4daafa98b558005: Bootstrap starting.
I20260812 06:20:05.283430 27863 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P ad060527d7ec4dfaa4daafa98b558005: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:05.284297 27863 log.cc:826] T 00000000000000000000000000000000 P ad060527d7ec4dfaa4daafa98b558005: Log is configured to *not* fsync() on all Append() calls
I20260812 06:20:05.285863 27863 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ad060527d7ec4dfaa4daafa98b558005: No bootstrap required, opened a new log
I20260812 06:20:05.288486 27863 raft_consensus.cc:359] T 00000000000000000000000000000000 P ad060527d7ec4dfaa4daafa98b558005 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ad060527d7ec4dfaa4daafa98b558005" member_type: VOTER }
I20260812 06:20:05.288635 27863 raft_consensus.cc:385] T 00000000000000000000000000000000 P ad060527d7ec4dfaa4daafa98b558005 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:05.288717 27863 raft_consensus.cc:740] T 00000000000000000000000000000000 P ad060527d7ec4dfaa4daafa98b558005 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ad060527d7ec4dfaa4daafa98b558005, State: Initialized, Role: FOLLOWER
I20260812 06:20:05.289273 27863 consensus_queue.cc:260] T 00000000000000000000000000000000 P ad060527d7ec4dfaa4daafa98b558005 [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: "ad060527d7ec4dfaa4daafa98b558005" member_type: VOTER }
I20260812 06:20:05.289422 27863 raft_consensus.cc:399] T 00000000000000000000000000000000 P ad060527d7ec4dfaa4daafa98b558005 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:05.289502 27863 raft_consensus.cc:493] T 00000000000000000000000000000000 P ad060527d7ec4dfaa4daafa98b558005 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:05.289661 27863 raft_consensus.cc:3060] T 00000000000000000000000000000000 P ad060527d7ec4dfaa4daafa98b558005 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:05.290372 27863 raft_consensus.cc:515] T 00000000000000000000000000000000 P ad060527d7ec4dfaa4daafa98b558005 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ad060527d7ec4dfaa4daafa98b558005" member_type: VOTER }
I20260812 06:20:05.290798 27863 leader_election.cc:304] T 00000000000000000000000000000000 P ad060527d7ec4dfaa4daafa98b558005 [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: ad060527d7ec4dfaa4daafa98b558005; no voters: 
I20260812 06:20:05.291123 27863 leader_election.cc:290] T 00000000000000000000000000000000 P ad060527d7ec4dfaa4daafa98b558005 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:05.291273 27871 raft_consensus.cc:2804] T 00000000000000000000000000000000 P ad060527d7ec4dfaa4daafa98b558005 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:05.291543 27871 raft_consensus.cc:697] T 00000000000000000000000000000000 P ad060527d7ec4dfaa4daafa98b558005 [term 1 LEADER]: Becoming Leader. State: Replica: ad060527d7ec4dfaa4daafa98b558005, State: Running, Role: LEADER
I20260812 06:20:05.291921 27871 consensus_queue.cc:237] T 00000000000000000000000000000000 P ad060527d7ec4dfaa4daafa98b558005 [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: "ad060527d7ec4dfaa4daafa98b558005" member_type: VOTER }
I20260812 06:20:05.292071 27863 sys_catalog.cc:565] T 00000000000000000000000000000000 P ad060527d7ec4dfaa4daafa98b558005 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:05.293876 27873 sys_catalog.cc:455] T 00000000000000000000000000000000 P ad060527d7ec4dfaa4daafa98b558005 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "ad060527d7ec4dfaa4daafa98b558005" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ad060527d7ec4dfaa4daafa98b558005" member_type: VOTER } }
I20260812 06:20:05.293637 27874 sys_catalog.cc:455] T 00000000000000000000000000000000 P ad060527d7ec4dfaa4daafa98b558005 [sys.catalog]: SysCatalogTable state changed. Reason: New leader ad060527d7ec4dfaa4daafa98b558005. Latest consensus state: current_term: 1 leader_uuid: "ad060527d7ec4dfaa4daafa98b558005" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ad060527d7ec4dfaa4daafa98b558005" member_type: VOTER } }
I20260812 06:20:05.294088 27873 sys_catalog.cc:458] T 00000000000000000000000000000000 P ad060527d7ec4dfaa4daafa98b558005 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:05.294088 27874 sys_catalog.cc:458] T 00000000000000000000000000000000 P ad060527d7ec4dfaa4daafa98b558005 [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:05.294446 27737 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:05.294610 27899 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:05.297103 27899 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:05.301622 27899 catalog_manager.cc:1383] Generated new cluster ID: 598a21dd1df746f8a5712455fb0685e4
I20260812 06:20:05.301688 27899 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:05.318418 27899 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:05.319312 27899 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:05.332751 27899 catalog_manager.cc:6092] T 00000000000000000000000000000000 P ad060527d7ec4dfaa4daafa98b558005: Generated new TSK 0
I20260812 06:20:05.333348 27899 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:05.359302 27737 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:05.362584 27912 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:20:05.362668 27908 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:20:05.362684 27737 server_base.cc:1061] running on GCE node
W20260812 06:20:05.362623 27907 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:20:05.362987 27737 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:05.363060 27737 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:20:05.363085 27737 hybrid_clock.cc:648] HybridClock initialized: now 1786515605363085 us; error 0 us; skew 500 ppm
I20260812 06:20:05.364034 27737 webserver.cc:533] Webserver started at http://127.27.22.65:38919/ using document root <none> and password file <none>
I20260812 06:20:05.364202 27737 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:05.364261 27737 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:05.364337 27737 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:05.364768 27737 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root/instance:
uuid: "500cb27693ec4f519eb3339534e9aa27"
format_stamp: "Formatted at 2026-08-12 06:20:05 on dist-test-slave-92m1"
I20260812 06:20:05.366596 27737 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:05.367707 27922 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:20:05.367976 27737 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.000s
I20260812 06:20:05.368072 27737 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root
uuid: "500cb27693ec4f519eb3339534e9aa27"
format_stamp: "Formatted at 2026-08-12 06:20:05 on dist-test-slave-92m1"
I20260812 06:20:05.368155 27737 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-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:20:05.399290 27737 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:05.399744 27737 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:05.400257 27737 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:05.401074 27737 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:05.401145 27737 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:05.401222 27737 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:05.401263 27737 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:05.407804 27737 rpc_server.cc:307] RPC server started. Bound to: 127.27.22.65:42875
I20260812 06:20:05.407858 28035 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.22.65:42875 every 8 connection(s)
I20260812 06:20:05.420785 28037 heartbeater.cc:344] Connected to a master server at 127.27.22.126:39897
I20260812 06:20:05.421051 28037 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:05.421447 28037 heartbeater.cc:507] Master 127.27.22.126:39897 requested a full tablet report, sending...
I20260812 06:20:05.422760 27791 ts_manager.cc:194] Registered new tserver with Master: 500cb27693ec4f519eb3339534e9aa27 (127.27.22.65:42875)
I20260812 06:20:05.422849 27737 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01436754s
I20260812 06:20:05.424078 27791 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:46504
I20260812 06:20:05.432623 27791 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:46506:
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:20:05.445967 27967 tablet_service.cc:1511] Processing CreateTablet for tablet fdc613d3ea7e4164b3224766796088a1 (DEFAULT_TABLE table=heavy-update-compaction-test [id=c978e0523ced42df96e934d819e7c95d]), partition=
I20260812 06:20:05.446440 27967 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet fdc613d3ea7e4164b3224766796088a1. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:05.448654 28058 tablet_bootstrap.cc:492] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Bootstrap starting.
I20260812 06:20:05.449633 28058 tablet_bootstrap.cc:654] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:05.450767 28058 tablet_bootstrap.cc:492] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: No bootstrap required, opened a new log
I20260812 06:20:05.450866 28058 ts_tablet_manager.cc:1403] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:05.451361 28058 raft_consensus.cc:359] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "500cb27693ec4f519eb3339534e9aa27" member_type: VOTER last_known_addr { host: "127.27.22.65" port: 42875 } }
I20260812 06:20:05.451460 28058 raft_consensus.cc:385] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:05.451485 28058 raft_consensus.cc:740] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 500cb27693ec4f519eb3339534e9aa27, State: Initialized, Role: FOLLOWER
I20260812 06:20:05.451737 28058 consensus_queue.cc:260] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27 [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: "500cb27693ec4f519eb3339534e9aa27" member_type: VOTER last_known_addr { host: "127.27.22.65" port: 42875 } }
I20260812 06:20:05.451853 28058 raft_consensus.cc:399] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:05.451915 28058 raft_consensus.cc:493] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:05.451974 28058 raft_consensus.cc:3060] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:05.452620 28058 raft_consensus.cc:515] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "500cb27693ec4f519eb3339534e9aa27" member_type: VOTER last_known_addr { host: "127.27.22.65" port: 42875 } }
I20260812 06:20:05.452760 28058 leader_election.cc:304] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27 [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: 500cb27693ec4f519eb3339534e9aa27; no voters: 
I20260812 06:20:05.452986 28058 leader_election.cc:290] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:05.453081 28062 raft_consensus.cc:2804] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:05.453250 28062 raft_consensus.cc:697] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27 [term 1 LEADER]: Becoming Leader. State: Replica: 500cb27693ec4f519eb3339534e9aa27, State: Running, Role: LEADER
I20260812 06:20:05.453367 28058 ts_tablet_manager.cc:1434] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:20:05.453454 28062 consensus_queue.cc:237] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27 [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: "500cb27693ec4f519eb3339534e9aa27" member_type: VOTER last_known_addr { host: "127.27.22.65" port: 42875 } }
I20260812 06:20:05.453790 28037 heartbeater.cc:499] Master 127.27.22.126:39897 was elected leader, sending a full tablet report...
I20260812 06:20:05.456081 27791 catalog_manager.cc:5719] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27 reported cstate change: term changed from 0 to 1, leader changed from <none> to 500cb27693ec4f519eb3339534e9aa27 (127.27.22.65). New cstate: current_term: 1 leader_uuid: "500cb27693ec4f519eb3339534e9aa27" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "500cb27693ec4f519eb3339534e9aa27" member_type: VOTER last_known_addr { host: "127.27.22.65" port: 42875 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:05.513593 27737 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.052s	user 0.023s	sys 0.001s
I20260812 06:20:05.659125 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushMRSOp(fdc613d3ea7e4164b3224766796088a1): perf score=19.054940
I20260812 06:20:05.826045 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushMRSOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.166s	user 0.140s	sys 0.016s Metrics: {"bytes_written":12307492,"cfile_init":1,"compiler_manager_pool.queue_time_us":832,"delete_count":0,"dirs.queue_time_us":46,"dirs.run_cpu_time_us":182,"dirs.run_wall_time_us":703,"drs_written":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40405,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":161,"threads_started":1,"update_count":1500}
I20260812 06:20:05.827328 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling LogGCOp(fdc613d3ea7e4164b3224766796088a1): free 20743831 bytes of WAL
I20260812 06:20:05.827684 27929 log_reader.cc:385] T fdc613d3ea7e4164b3224766796088a1: removed 2 log segments from log reader
I20260812 06:20:05.827766 27929 log.cc:1079] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/fdc613d3ea7e4164b3224766796088a1/wal-000000001 (ops 1-6)
I20260812 06:20:05.827829 27929 log.cc:1079] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/fdc613d3ea7e4164b3224766796088a1/wal-000000002 (ops 7-11)
I20260812 06:20:05.833753 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: LogGCOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.006s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:20:05.834149 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling UndoDeltaBlockGCOp(fdc613d3ea7e4164b3224766796088a1): 16411392 bytes on disk
I20260812 06:20:05.834805 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: UndoDeltaBlockGCOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4}
I20260812 06:20:05.835294 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=2.188937
I20260812 06:20:05.857734 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.022s	user 0.003s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6948,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:05.858304 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling MajorDeltaCompactionOp(fdc613d3ea7e4164b3224766796088a1): perf score=1.000000
I20260812 06:20:06.012012 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: MajorDeltaCompactionOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.154s	user 0.081s	sys 0.068s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":911,"lbm_read_time_us":8286,"lbm_reads_lt_1ms":460,"lbm_write_time_us":24233,"lbm_writes_lt_1ms":443,"mutex_wait_us":31,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18304,"thread_start_us":412,"threads_started":5,"update_count":2000}
I20260812 06:20:06.012560 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=10.126437
I20260812 06:20:06.051427 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.039s	user 0.015s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14198,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:06.052122 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=2.188937
I20260812 06:20:06.064316 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4630,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:06.064877 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling MajorDeltaCompactionOp(fdc613d3ea7e4164b3224766796088a1): perf score=1.000000
I20260812 06:20:06.211270 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: MajorDeltaCompactionOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.146s	user 0.113s	sys 0.033s 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":470,"lbm_read_time_us":10294,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28564,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19200,"update_count":2000}
I20260812 06:20:06.211949 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=10.126437
I20260812 06:20:06.254285 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.042s	user 0.023s	sys 0.013s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17104,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:06.254766 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=2.188937
I20260812 06:20:06.265028 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4020,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:06.265434 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling MajorDeltaCompactionOp(fdc613d3ea7e4164b3224766796088a1): perf score=1.000000
I20260812 06:20:06.388362 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: MajorDeltaCompactionOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.123s	user 0.110s	sys 0.012s 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":677,"lbm_read_time_us":7653,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24194,"lbm_writes_lt_1ms":443,"mutex_wait_us":288,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":88960,"update_count":2000}
I20260812 06:20:06.388938 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=10.126437
I20260812 06:20:06.433313 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.044s	user 0.008s	sys 0.030s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13388,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:06.433885 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=2.188937
I20260812 06:20:06.445004 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4439,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:06.445461 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling MajorDeltaCompactionOp(fdc613d3ea7e4164b3224766796088a1): perf score=1.000000
I20260812 06:20:06.592644 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: MajorDeltaCompactionOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.147s	user 0.081s	sys 0.059s 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":281,"lbm_read_time_us":11215,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21992,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:20:06.593240 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=10.126437
I20260812 06:20:06.645234 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.052s	user 0.023s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17865,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:06.645694 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=2.188937
I20260812 06:20:06.656963 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4054,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:06.657553 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling MajorDeltaCompactionOp(fdc613d3ea7e4164b3224766796088a1): perf score=1.000000
I20260812 06:20:06.784044 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: MajorDeltaCompactionOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.126s	user 0.102s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":296,"lbm_read_time_us":8273,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24659,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15104,"update_count":2000}
I20260812 06:20:06.784904 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=10.126437
I20260812 06:20:06.828567 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.043s	user 0.033s	sys 0.007s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":18270,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:06.829039 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=2.188937
I20260812 06:20:06.840178 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4249,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:06.840874 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling MajorDeltaCompactionOp(fdc613d3ea7e4164b3224766796088a1): perf score=1.000000
I20260812 06:20:06.969889 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: MajorDeltaCompactionOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.129s	user 0.101s	sys 0.028s 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":143,"lbm_read_time_us":9529,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25250,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2000}
I20260812 06:20:06.970558 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=10.126437
I20260812 06:20:07.015618 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.045s	user 0.033s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19804,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:07.016151 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=2.188937
I20260812 06:20:07.028424 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4519,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:07.028915 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushMRSOp(fdc613d3ea7e4164b3224766796088a1): perf score=1.000000
I20260812 06:20:07.062218 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushMRSOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.033s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":173,"dirs.run_wall_time_us":1223,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1757,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28,"spinlock_wait_cycles":17024}
I20260812 06:20:07.063129 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling LogGCOp(fdc613d3ea7e4164b3224766796088a1): free 112239308 bytes of WAL
I20260812 06:20:07.063386 27929 log_reader.cc:385] T fdc613d3ea7e4164b3224766796088a1: removed 11 log segments from log reader
I20260812 06:20:07.063459 27929 log.cc:1079] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/fdc613d3ea7e4164b3224766796088a1/wal-000000003 (ops 12-16)
I20260812 06:20:07.063505 27929 log.cc:1079] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/fdc613d3ea7e4164b3224766796088a1/wal-000000004 (ops 17-21)
I20260812 06:20:07.063540 27929 log.cc:1079] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/fdc613d3ea7e4164b3224766796088a1/wal-000000005 (ops 22-26)
I20260812 06:20:07.063604 27929 log.cc:1079] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/fdc613d3ea7e4164b3224766796088a1/wal-000000006 (ops 27-30)
I20260812 06:20:07.063643 27929 log.cc:1079] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/fdc613d3ea7e4164b3224766796088a1/wal-000000007 (ops 31-35)
I20260812 06:20:07.063683 27929 log.cc:1079] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/fdc613d3ea7e4164b3224766796088a1/wal-000000008 (ops 36-40)
I20260812 06:20:07.063725 27929 log.cc:1079] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/fdc613d3ea7e4164b3224766796088a1/wal-000000009 (ops 41-45)
I20260812 06:20:07.063764 27929 log.cc:1079] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/fdc613d3ea7e4164b3224766796088a1/wal-000000010 (ops 46-50)
I20260812 06:20:07.063803 27929 log.cc:1079] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/fdc613d3ea7e4164b3224766796088a1/wal-000000011 (ops 51-55)
I20260812 06:20:07.063843 27929 log.cc:1079] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/fdc613d3ea7e4164b3224766796088a1/wal-000000012 (ops 56-60)
I20260812 06:20:07.063880 27929 log.cc:1079] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/fdc613d3ea7e4164b3224766796088a1/wal-000000013 (ops 61-65)
I20260812 06:20:07.089859 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: LogGCOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.027s	user 0.004s	sys 0.020s Metrics: {}
I20260812 06:20:07.090262 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=3.181125
I20260812 06:20:07.108084 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.018s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":7122,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:07.108551 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=2.188937
I20260812 06:20:07.118480 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3848,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:07.119145 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling UndoDeltaBlockGCOp(fdc613d3ea7e4164b3224766796088a1): 448 bytes on disk
I20260812 06:20:07.119809 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: UndoDeltaBlockGCOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":124,"lbm_reads_lt_1ms":4}
I20260812 06:20:07.120512 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling MajorDeltaCompactionOp(fdc613d3ea7e4164b3224766796088a1): perf score=1.000000
I20260812 06:20:07.289947 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: MajorDeltaCompactionOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.169s	user 0.127s	sys 0.039s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877324,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":446,"lbm_read_time_us":11086,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35907,"lbm_writes_lt_1ms":643,"mutex_wait_us":26,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12288,"thread_start_us":81,"threads_started":1,"update_count":3000}
I20260812 06:20:07.290637 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=14.095187
I20260812 06:20:07.341884 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.051s	user 0.022s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20517,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:07.342379 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=2.188937
I20260812 06:20:07.353917 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4306,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:07.354403 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling MajorDeltaCompactionOp(fdc613d3ea7e4164b3224766796088a1): perf score=1.000000
I20260812 06:20:07.520067 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: MajorDeltaCompactionOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.165s	user 0.115s	sys 0.043s 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":268,"lbm_read_time_us":11844,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31032,"lbm_writes_lt_1ms":543,"mutex_wait_us":45,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":2500}
I20260812 06:20:07.520671 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=14.095187
I20260812 06:20:07.575407 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.055s	user 0.040s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21841,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:07.575850 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling MajorDeltaCompactionOp(fdc613d3ea7e4164b3224766796088a1): perf score=1.000000
I20260812 06:20:07.727303 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: MajorDeltaCompactionOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.151s	user 0.088s	sys 0.055s 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":269,"lbm_read_time_us":9382,"lbm_reads_lt_1ms":463,"lbm_write_time_us":24791,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":96896,"update_count":2000}
I20260812 06:20:07.727942 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=14.095187
I20260812 06:20:07.776629 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.049s	user 0.031s	sys 0.009s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18708,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:07.777055 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=2.188937
I20260812 06:20:07.788005 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4297,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:07.788781 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling MajorDeltaCompactionOp(fdc613d3ea7e4164b3224766796088a1): perf score=1.000000
I20260812 06:20:07.976403 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: MajorDeltaCompactionOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.187s	user 0.131s	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":804,"lbm_read_time_us":10911,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27333,"lbm_writes_lt_1ms":543,"mutex_wait_us":46,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:20:07.977172 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=14.095187
I20260812 06:20:08.031910 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.054s	user 0.022s	sys 0.031s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24339,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:08.032461 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=2.188937
I20260812 06:20:08.049079 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.016s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6368,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:08.049528 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling MajorDeltaCompactionOp(fdc613d3ea7e4164b3224766796088a1): perf score=1.000000
I20260812 06:20:08.223361 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: MajorDeltaCompactionOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.174s	user 0.124s	sys 0.046s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":332,"lbm_read_time_us":8549,"lbm_reads_lt_1ms":568,"lbm_write_time_us":37341,"lbm_writes_lt_1ms":543,"mutex_wait_us":38,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16000,"update_count":2500}
I20260812 06:20:08.223939 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=14.095187
I20260812 06:20:08.272017 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.048s	user 0.032s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19965,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:08.272449 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=2.188937
I20260812 06:20:08.283795 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.011s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4059,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:08.284240 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling MajorDeltaCompactionOp(fdc613d3ea7e4164b3224766796088a1): perf score=1.000000
I20260812 06:20:08.433512 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: MajorDeltaCompactionOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.149s	user 0.113s	sys 0.036s 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":842,"lbm_read_time_us":11239,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30054,"lbm_writes_lt_1ms":543,"mutex_wait_us":253,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2500}
I20260812 06:20:08.434031 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=11.118625
I20260812 06:20:08.473464 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.039s	user 0.018s	sys 0.019s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":17051,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:08.473964 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=2.188937
I20260812 06:20:08.496472 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.022s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5527,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:08.496946 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=2.188937
I20260812 06:20:08.507987 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4147,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:08.508716 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushMRSOp(fdc613d3ea7e4164b3224766796088a1): perf score=1.000000
I20260812 06:20:08.544452 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushMRSOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.035s	user 0.030s	sys 0.004s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":53,"dirs.run_cpu_time_us":239,"dirs.run_wall_time_us":1192,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1824,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:20:08.545157 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling LogGCOp(fdc613d3ea7e4164b3224766796088a1): free 124710298 bytes of WAL
I20260812 06:20:08.545382 27929 log_reader.cc:385] T fdc613d3ea7e4164b3224766796088a1: removed 12 log segments from log reader
I20260812 06:20:08.545446 27929 log.cc:1079] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/fdc613d3ea7e4164b3224766796088a1/wal-000000014 (ops 66-70)
I20260812 06:20:08.545500 27929 log.cc:1079] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/fdc613d3ea7e4164b3224766796088a1/wal-000000015 (ops 71-75)
I20260812 06:20:08.545554 27929 log.cc:1079] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/fdc613d3ea7e4164b3224766796088a1/wal-000000016 (ops 76-80)
I20260812 06:20:08.545596 27929 log.cc:1079] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/fdc613d3ea7e4164b3224766796088a1/wal-000000017 (ops 81-85)
I20260812 06:20:08.545634 27929 log.cc:1079] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/fdc613d3ea7e4164b3224766796088a1/wal-000000018 (ops 86-90)
I20260812 06:20:08.545671 27929 log.cc:1079] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/fdc613d3ea7e4164b3224766796088a1/wal-000000019 (ops 91-95)
I20260812 06:20:08.545710 27929 log.cc:1079] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/fdc613d3ea7e4164b3224766796088a1/wal-000000020 (ops 96-100)
I20260812 06:20:08.545748 27929 log.cc:1079] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/fdc613d3ea7e4164b3224766796088a1/wal-000000021 (ops 101-105)
I20260812 06:20:08.545784 27929 log.cc:1079] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/fdc613d3ea7e4164b3224766796088a1/wal-000000022 (ops 106-110)
I20260812 06:20:08.545822 27929 log.cc:1079] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/fdc613d3ea7e4164b3224766796088a1/wal-000000023 (ops 111-115)
I20260812 06:20:08.545859 27929 log.cc:1079] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/fdc613d3ea7e4164b3224766796088a1/wal-000000024 (ops 116-120)
I20260812 06:20:08.545895 27929 log.cc:1079] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/fdc613d3ea7e4164b3224766796088a1/wal-000000025 (ops 121-125)
I20260812 06:20:08.570392 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: LogGCOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.025s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:20:08.570873 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=4.173312
I20260812 06:20:08.584318 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.013s	user 0.004s	sys 0.009s Metrics: {"bytes_written":5374417,"delete_count":0,"lbm_write_time_us":5556,"lbm_writes_lt_1ms":134,"reinsert_count":0,"update_count":655}
I20260812 06:20:08.584884 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling UndoDeltaBlockGCOp(fdc613d3ea7e4164b3224766796088a1): 481 bytes on disk
I20260812 06:20:08.585309 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: UndoDeltaBlockGCOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:20:08.585884 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=1.196750
I20260812 06:20:08.607230 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.021s	user 0.005s	sys 0.012s Metrics: {"bytes_written":2830880,"delete_count":0,"lbm_write_time_us":3752,"lbm_writes_lt_1ms":72,"reinsert_count":0,"update_count":345}
I20260812 06:20:08.607880 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling MajorDeltaCompactionOp(fdc613d3ea7e4164b3224766796088a1): perf score=1.000000
I20260812 06:20:08.820412 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: MajorDeltaCompactionOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.212s	user 0.132s	sys 0.080s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979833,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":678,"lbm_read_time_us":14704,"lbm_reads_lt_1ms":767,"lbm_write_time_us":36387,"lbm_writes_lt_1ms":743,"mutex_wait_us":25,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":50816,"thread_start_us":85,"threads_started":1,"update_count":3500}
I20260812 06:20:08.821179 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=18.063937
I20260812 06:20:08.904958 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.084s	user 0.047s	sys 0.035s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":33747,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:08.905692 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=2.188937
I20260812 06:20:08.916908 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4379,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:08.917516 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling MajorDeltaCompactionOp(fdc613d3ea7e4164b3224766796088a1): perf score=1.000000
I20260812 06:20:09.122328 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: MajorDeltaCompactionOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.205s	user 0.142s	sys 0.061s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1288,"lbm_read_time_us":13993,"lbm_reads_lt_1ms":672,"lbm_write_time_us":39801,"lbm_writes_lt_1ms":643,"mutex_wait_us":374,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":3000}
I20260812 06:20:09.123041 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=14.095187
I20260812 06:20:09.182986 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.060s	user 0.034s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24443,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:20:09.183624 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=2.188937
I20260812 06:20:09.195022 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4519,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:09.195487 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling MajorDeltaCompactionOp(fdc613d3ea7e4164b3224766796088a1): perf score=1.000000
I20260812 06:20:09.373714 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: MajorDeltaCompactionOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.178s	user 0.106s	sys 0.070s 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":1148,"lbm_read_time_us":12184,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32093,"lbm_writes_lt_1ms":543,"mutex_wait_us":346,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2500}
I20260812 06:20:09.374388 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=14.095187
I20260812 06:20:09.429610 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.055s	user 0.019s	sys 0.033s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22304,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:09.430169 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=2.188937
I20260812 06:20:09.440933 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4254,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:09.441373 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling MajorDeltaCompactionOp(fdc613d3ea7e4164b3224766796088a1): perf score=1.000000
I20260812 06:20:09.637782 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: MajorDeltaCompactionOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.196s	user 0.126s	sys 0.059s 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":582,"lbm_read_time_us":14435,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30476,"lbm_writes_lt_1ms":543,"mutex_wait_us":262,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2500}
I20260812 06:20:09.638485 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=14.095187
I20260812 06:20:09.695247 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.057s	user 0.028s	sys 0.022s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20352,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:09.695850 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=2.188937
I20260812 06:20:09.706326 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4265,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:09.706753 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling MajorDeltaCompactionOp(fdc613d3ea7e4164b3224766796088a1): perf score=1.000000
I20260812 06:20:09.911289 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: MajorDeltaCompactionOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.204s	user 0.144s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":522,"lbm_read_time_us":14432,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31574,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:20:09.911746 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=14.095187
I20260812 06:20:09.966080 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.054s	user 0.035s	sys 0.017s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22081,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:09.966548 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=2.188937
I20260812 06:20:09.978602 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4565,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:09.979272 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushMRSOp(fdc613d3ea7e4164b3224766796088a1): perf score=1.000000
I20260812 06:20:10.008478 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushMRSOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.029s	user 0.019s	sys 0.007s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":133,"dirs.run_cpu_time_us":228,"dirs.run_wall_time_us":1176,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1647,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:10.009194 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling LogGCOp(fdc613d3ea7e4164b3224766796088a1): free 120553683 bytes of WAL
I20260812 06:20:10.009423 27929 log_reader.cc:385] T fdc613d3ea7e4164b3224766796088a1: removed 12 log segments from log reader
I20260812 06:20:10.009469 27929 log.cc:1079] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/fdc613d3ea7e4164b3224766796088a1/wal-000000026 (ops 126-130)
I20260812 06:20:10.009497 27929 log.cc:1079] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/fdc613d3ea7e4164b3224766796088a1/wal-000000027 (ops 131-135)
I20260812 06:20:10.009552 27929 log.cc:1079] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/fdc613d3ea7e4164b3224766796088a1/wal-000000028 (ops 136-140)
I20260812 06:20:10.009591 27929 log.cc:1079] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/fdc613d3ea7e4164b3224766796088a1/wal-000000029 (ops 141-144)
I20260812 06:20:10.009635 27929 log.cc:1079] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/fdc613d3ea7e4164b3224766796088a1/wal-000000030 (ops 145-149)
I20260812 06:20:10.009690 27929 log.cc:1079] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/fdc613d3ea7e4164b3224766796088a1/wal-000000031 (ops 150-154)
I20260812 06:20:10.009743 27929 log.cc:1079] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/fdc613d3ea7e4164b3224766796088a1/wal-000000032 (ops 155-159)
I20260812 06:20:10.009781 27929 log.cc:1079] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/fdc613d3ea7e4164b3224766796088a1/wal-000000033 (ops 160-164)
I20260812 06:20:10.009819 27929 log.cc:1079] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/fdc613d3ea7e4164b3224766796088a1/wal-000000034 (ops 165-168)
I20260812 06:20:10.009857 27929 log.cc:1079] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/fdc613d3ea7e4164b3224766796088a1/wal-000000035 (ops 169-173)
I20260812 06:20:10.009895 27929 log.cc:1079] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/fdc613d3ea7e4164b3224766796088a1/wal-000000036 (ops 174-178)
I20260812 06:20:10.009933 27929 log.cc:1079] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/fdc613d3ea7e4164b3224766796088a1/wal-000000037 (ops 179-183)
I20260812 06:20:10.035703 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: LogGCOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.026s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:20:10.036094 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=2.188937
I20260812 06:20:10.054440 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.018s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4441,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:10.054898 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=2.188937
I20260812 06:20:10.065306 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4059,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:10.065814 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling UndoDeltaBlockGCOp(fdc613d3ea7e4164b3224766796088a1): 448 bytes on disk
I20260812 06:20:10.066236 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: UndoDeltaBlockGCOp(fdc613d3ea7e4164b3224766796088a1) 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:20:10.066781 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling MajorDeltaCompactionOp(fdc613d3ea7e4164b3224766796088a1): perf score=1.000000
I20260812 06:20:10.308012 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: MajorDeltaCompactionOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.241s	user 0.141s	sys 0.092s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979749,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1595,"lbm_read_time_us":15000,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40676,"lbm_writes_lt_1ms":743,"mutex_wait_us":1185,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":33920,"thread_start_us":83,"threads_started":1,"update_count":3500}
I20260812 06:20:10.308634 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=18.063937
I20260812 06:20:10.380564 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.072s	user 0.045s	sys 0.017s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":28561,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:10.381028 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1): perf score=2.188937
I20260812 06:20:10.391350 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: FlushDeltaMemStoresOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3876,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:10.391822 28039 maintenance_manager.cc:419] P 500cb27693ec4f519eb3339534e9aa27: Scheduling MajorDeltaCompactionOp(fdc613d3ea7e4164b3224766796088a1): perf score=1.000000
I20260812 06:20:10.421778 27737 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.908s	user 1.807s	sys 0.138s
I20260812 06:20:10.501318 27737 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.079s	user 0.000s	sys 0.001s
I20260812 06:20:10.501932 27737 tablet_server.cc:179] TabletServer@127.27.22.65:0 shutting down...
I20260812 06:20:10.563485 27929 maintenance_manager.cc:643] P 500cb27693ec4f519eb3339534e9aa27: MajorDeltaCompactionOp(fdc613d3ea7e4164b3224766796088a1) complete. Timing: real 0.171s	user 0.103s	sys 0.068s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":471,"lbm_read_time_us":13665,"lbm_reads_lt_1ms":668,"lbm_write_time_us":29926,"lbm_writes_lt_1ms":643,"mutex_wait_us":101,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7680,"update_count":3000}
I20260812 06:20:10.564265 27737 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:10.564706 27737 tablet_replica.cc:333] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27: stopping tablet replica
I20260812 06:20:10.564942 27737 raft_consensus.cc:2243] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:10.565177 27737 raft_consensus.cc:2272] T fdc613d3ea7e4164b3224766796088a1 P 500cb27693ec4f519eb3339534e9aa27 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:10.580770 27737 tablet_server.cc:196] TabletServer@127.27.22.65:0 shutdown complete.
I20260812 06:20:10.617231 27737 master.cc:562] Master@127.27.22.126:39897 shutting down...
I20260812 06:20:10.620693 27737 raft_consensus.cc:2243] T 00000000000000000000000000000000 P ad060527d7ec4dfaa4daafa98b558005 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:10.620886 27737 raft_consensus.cc:2272] T 00000000000000000000000000000000 P ad060527d7ec4dfaa4daafa98b558005 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:10.620972 27737 tablet_replica.cc:333] T 00000000000000000000000000000000 P ad060527d7ec4dfaa4daafa98b558005: stopping tablet replica
I20260812 06:20:10.633104 27737 master.cc:584] Master@127.27.22.126:39897 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5490 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:20:10.731709 27737 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.27.22.126:34219
I20260812 06:20:10.732125 27737 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:10.734203 28091 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:20:10.734220 28094 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:20:10.734349 28096 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:20:10.734313 27737 server_base.cc:1061] running on GCE node
I20260812 06:20:10.734658 27737 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:10.734711 27737 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:20:10.734728 27737 hybrid_clock.cc:648] HybridClock initialized: now 1786515610734728 us; error 0 us; skew 500 ppm
I20260812 06:20:10.735736 27737 webserver.cc:533] Webserver started at http://127.27.22.126:33903/ using document root <none> and password file <none>
I20260812 06:20:10.735919 27737 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:10.735975 27737 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:10.736057 27737 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:10.736471 27737 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/master-0-root/instance:
uuid: "15a62c41fb2e4195ad31365af1324fdd"
format_stamp: "Formatted at 2026-08-12 06:20:10 on dist-test-slave-92m1"
I20260812 06:20:10.737921 27737 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:10.738754 28103 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:20:10.739053 27737 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:10.739125 27737 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/master-0-root
uuid: "15a62c41fb2e4195ad31365af1324fdd"
format_stamp: "Formatted at 2026-08-12 06:20:10 on dist-test-slave-92m1"
I20260812 06:20:10.739181 27737 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-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:20:10.747653 27737 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:10.747939 27737 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:10.751807 27737 rpc_server.cc:307] RPC server started. Bound to: 127.27.22.126:34219
I20260812 06:20:10.753358 28195 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.22.126:34219 every 8 connection(s)
I20260812 06:20:10.756793 28196 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:20:10.758658 28196 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 15a62c41fb2e4195ad31365af1324fdd: Bootstrap starting.
I20260812 06:20:10.759439 28196 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 15a62c41fb2e4195ad31365af1324fdd: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:10.760336 28196 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 15a62c41fb2e4195ad31365af1324fdd: No bootstrap required, opened a new log
I20260812 06:20:10.760807 28196 raft_consensus.cc:359] T 00000000000000000000000000000000 P 15a62c41fb2e4195ad31365af1324fdd [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "15a62c41fb2e4195ad31365af1324fdd" member_type: VOTER }
I20260812 06:20:10.760903 28196 raft_consensus.cc:385] T 00000000000000000000000000000000 P 15a62c41fb2e4195ad31365af1324fdd [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:10.760938 28196 raft_consensus.cc:740] T 00000000000000000000000000000000 P 15a62c41fb2e4195ad31365af1324fdd [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 15a62c41fb2e4195ad31365af1324fdd, State: Initialized, Role: FOLLOWER
I20260812 06:20:10.761098 28196 consensus_queue.cc:260] T 00000000000000000000000000000000 P 15a62c41fb2e4195ad31365af1324fdd [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: "15a62c41fb2e4195ad31365af1324fdd" member_type: VOTER }
I20260812 06:20:10.761189 28196 raft_consensus.cc:399] T 00000000000000000000000000000000 P 15a62c41fb2e4195ad31365af1324fdd [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:10.761214 28196 raft_consensus.cc:493] T 00000000000000000000000000000000 P 15a62c41fb2e4195ad31365af1324fdd [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:10.761251 28196 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 15a62c41fb2e4195ad31365af1324fdd [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:10.761895 28196 raft_consensus.cc:515] T 00000000000000000000000000000000 P 15a62c41fb2e4195ad31365af1324fdd [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "15a62c41fb2e4195ad31365af1324fdd" member_type: VOTER }
I20260812 06:20:10.762044 28196 leader_election.cc:304] T 00000000000000000000000000000000 P 15a62c41fb2e4195ad31365af1324fdd [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: 15a62c41fb2e4195ad31365af1324fdd; no voters: 
I20260812 06:20:10.762224 28196 leader_election.cc:290] T 00000000000000000000000000000000 P 15a62c41fb2e4195ad31365af1324fdd [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:10.762317 28208 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 15a62c41fb2e4195ad31365af1324fdd [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:10.762503 28208 raft_consensus.cc:697] T 00000000000000000000000000000000 P 15a62c41fb2e4195ad31365af1324fdd [term 1 LEADER]: Becoming Leader. State: Replica: 15a62c41fb2e4195ad31365af1324fdd, State: Running, Role: LEADER
I20260812 06:20:10.762686 28196 sys_catalog.cc:565] T 00000000000000000000000000000000 P 15a62c41fb2e4195ad31365af1324fdd [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:10.762687 28208 consensus_queue.cc:237] T 00000000000000000000000000000000 P 15a62c41fb2e4195ad31365af1324fdd [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: "15a62c41fb2e4195ad31365af1324fdd" member_type: VOTER }
I20260812 06:20:10.763163 28210 sys_catalog.cc:455] T 00000000000000000000000000000000 P 15a62c41fb2e4195ad31365af1324fdd [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "15a62c41fb2e4195ad31365af1324fdd" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "15a62c41fb2e4195ad31365af1324fdd" member_type: VOTER } }
I20260812 06:20:10.763230 28214 sys_catalog.cc:455] T 00000000000000000000000000000000 P 15a62c41fb2e4195ad31365af1324fdd [sys.catalog]: SysCatalogTable state changed. Reason: New leader 15a62c41fb2e4195ad31365af1324fdd. Latest consensus state: current_term: 1 leader_uuid: "15a62c41fb2e4195ad31365af1324fdd" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "15a62c41fb2e4195ad31365af1324fdd" member_type: VOTER } }
I20260812 06:20:10.763342 28210 sys_catalog.cc:458] T 00000000000000000000000000000000 P 15a62c41fb2e4195ad31365af1324fdd [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:10.763444 28214 sys_catalog.cc:458] T 00000000000000000000000000000000 P 15a62c41fb2e4195ad31365af1324fdd [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:10.763972 28220 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:10.764657 28220 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:10.764834 27737 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:10.766502 28220 catalog_manager.cc:1383] Generated new cluster ID: 85161eb10141480f99e1ce5e11abd4b2
I20260812 06:20:10.766562 28220 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:10.781169 28220 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:10.781721 28220 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:10.790258 28220 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 15a62c41fb2e4195ad31365af1324fdd: Generated new TSK 0
I20260812 06:20:10.790441 28220 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:10.797315 27737 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:10.799631 28237 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:20:10.799595 27737 server_base.cc:1061] running on GCE node
W20260812 06:20:10.799615 28236 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:20:10.799751 28240 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:20:10.799999 27737 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:10.800071 27737 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:20:10.800097 27737 hybrid_clock.cc:648] HybridClock initialized: now 1786515610800097 us; error 0 us; skew 500 ppm
I20260812 06:20:10.800971 27737 webserver.cc:533] Webserver started at http://127.27.22.65:40319/ using document root <none> and password file <none>
I20260812 06:20:10.801167 27737 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:10.801239 27737 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:10.801321 27737 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:10.801738 27737 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/instance:
uuid: "33449c4ebb0c43fab3d0aff6845583fc"
format_stamp: "Formatted at 2026-08-12 06:20:10 on dist-test-slave-92m1"
I20260812 06:20:10.803310 27737 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:20:10.804292 28248 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:20:10.804584 27737 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:10.804664 27737 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root
uuid: "33449c4ebb0c43fab3d0aff6845583fc"
format_stamp: "Formatted at 2026-08-12 06:20:10 on dist-test-slave-92m1"
I20260812 06:20:10.804728 27737 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-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:20:10.820906 27737 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:10.821285 27737 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:10.821583 27737 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:10.822108 27737 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:10.822149 27737 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:10.822216 27737 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:10.822258 27737 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:10.827179 27737 rpc_server.cc:307] RPC server started. Bound to: 127.27.22.65:44843
I20260812 06:20:10.829512 28363 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.22.65:44843 every 8 connection(s)
I20260812 06:20:10.838376 28364 heartbeater.cc:344] Connected to a master server at 127.27.22.126:34219
I20260812 06:20:10.838514 28364 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:10.838779 28364 heartbeater.cc:507] Master 127.27.22.126:34219 requested a full tablet report, sending...
I20260812 06:20:10.839519 28134 ts_manager.cc:194] Registered new tserver with Master: 33449c4ebb0c43fab3d0aff6845583fc (127.27.22.65:44843)
I20260812 06:20:10.840224 27737 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012193086s
I20260812 06:20:10.840342 28134 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:46678
I20260812 06:20:10.847287 28134 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:46694:
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:20:10.856433 28300 tablet_service.cc:1511] Processing CreateTablet for tablet 736f1637c9c8409ab8c547b05f8604be (DEFAULT_TABLE table=heavy-update-compaction-test [id=0ab93868733b4b83a15a03a97d5349c4]), partition=
I20260812 06:20:10.856731 28300 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 736f1637c9c8409ab8c547b05f8604be. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:10.858789 28382 tablet_bootstrap.cc:492] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Bootstrap starting.
I20260812 06:20:10.859692 28382 tablet_bootstrap.cc:654] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:10.860716 28382 tablet_bootstrap.cc:492] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: No bootstrap required, opened a new log
I20260812 06:20:10.860826 28382 ts_tablet_manager.cc:1403] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Time spent bootstrapping tablet: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:20:10.861290 28382 raft_consensus.cc:359] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "33449c4ebb0c43fab3d0aff6845583fc" member_type: VOTER last_known_addr { host: "127.27.22.65" port: 44843 } }
I20260812 06:20:10.861421 28382 raft_consensus.cc:385] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:10.861483 28382 raft_consensus.cc:740] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 33449c4ebb0c43fab3d0aff6845583fc, State: Initialized, Role: FOLLOWER
I20260812 06:20:10.861637 28382 consensus_queue.cc:260] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc [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: "33449c4ebb0c43fab3d0aff6845583fc" member_type: VOTER last_known_addr { host: "127.27.22.65" port: 44843 } }
I20260812 06:20:10.861744 28382 raft_consensus.cc:399] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:10.861794 28382 raft_consensus.cc:493] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:10.861852 28382 raft_consensus.cc:3060] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:10.862560 28382 raft_consensus.cc:515] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "33449c4ebb0c43fab3d0aff6845583fc" member_type: VOTER last_known_addr { host: "127.27.22.65" port: 44843 } }
I20260812 06:20:10.862702 28382 leader_election.cc:304] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc [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: 33449c4ebb0c43fab3d0aff6845583fc; no voters: 
I20260812 06:20:10.862907 28382 leader_election.cc:290] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:10.863072 28385 raft_consensus.cc:2804] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:10.863260 28382 ts_tablet_manager.cc:1434] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:20:10.863315 28364 heartbeater.cc:499] Master 127.27.22.126:34219 was elected leader, sending a full tablet report...
I20260812 06:20:10.863400 28385 raft_consensus.cc:697] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc [term 1 LEADER]: Becoming Leader. State: Replica: 33449c4ebb0c43fab3d0aff6845583fc, State: Running, Role: LEADER
I20260812 06:20:10.863554 28385 consensus_queue.cc:237] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc [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: "33449c4ebb0c43fab3d0aff6845583fc" member_type: VOTER last_known_addr { host: "127.27.22.65" port: 44843 } }
I20260812 06:20:10.864859 28134 catalog_manager.cc:5719] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc reported cstate change: term changed from 0 to 1, leader changed from <none> to 33449c4ebb0c43fab3d0aff6845583fc (127.27.22.65). New cstate: current_term: 1 leader_uuid: "33449c4ebb0c43fab3d0aff6845583fc" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "33449c4ebb0c43fab3d0aff6845583fc" member_type: VOTER last_known_addr { host: "127.27.22.65" port: 44843 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:10.928818 27737 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.057s	user 0.022s	sys 0.004s
I20260812 06:20:11.079905 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushMRSOp(736f1637c9c8409ab8c547b05f8604be): perf score=19.054940
I20260812 06:20:11.245787 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushMRSOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.166s	user 0.083s	sys 0.080s Metrics: {"bytes_written":12389539,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":53,"dirs.run_cpu_time_us":216,"dirs.run_wall_time_us":992,"drs_written":1,"lbm_read_time_us":170,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42629,"lbm_writes_lt_1ms":759,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1510}
I20260812 06:20:11.246836 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling LogGCOp(736f1637c9c8409ab8c547b05f8604be): free 20743880 bytes of WAL
I20260812 06:20:11.247176 28254 log_reader.cc:385] T 736f1637c9c8409ab8c547b05f8604be: removed 2 log segments from log reader
I20260812 06:20:11.247299 28254 log.cc:1079] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/736f1637c9c8409ab8c547b05f8604be/wal-000000001 (ops 1-6)
I20260812 06:20:11.247366 28254 log.cc:1079] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/736f1637c9c8409ab8c547b05f8604be/wal-000000002 (ops 7-11)
I20260812 06:20:11.254629 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: LogGCOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.008s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:20:11.255074 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be): perf score=2.188937
I20260812 06:20:11.271363 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.016s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4020609,"delete_count":0,"lbm_write_time_us":6274,"lbm_writes_lt_1ms":101,"reinsert_count":0,"update_count":490}
I20260812 06:20:11.271863 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling MajorDeltaCompactionOp(736f1637c9c8409ab8c547b05f8604be): perf score=1.000000
I20260812 06:20:11.472306 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: MajorDeltaCompactionOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.200s	user 0.132s	sys 0.055s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":979,"lbm_read_time_us":12639,"lbm_reads_lt_1ms":468,"lbm_write_time_us":31426,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5376,"thread_start_us":384,"threads_started":5,"update_count":2000}
I20260812 06:20:11.472997 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be): perf score=14.095187
I20260812 06:20:11.540540 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.067s	user 0.043s	sys 0.023s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":25075,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:11.541174 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be): perf score=2.188937
I20260812 06:20:11.555297 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.014s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5782,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:11.555756 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling MajorDeltaCompactionOp(736f1637c9c8409ab8c547b05f8604be): perf score=1.000000
I20260812 06:20:11.754307 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: MajorDeltaCompactionOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.198s	user 0.125s	sys 0.072s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":547,"lbm_read_time_us":14245,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32739,"lbm_writes_lt_1ms":543,"mutex_wait_us":299,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:20:11.754786 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling UndoDeltaBlockGCOp(736f1637c9c8409ab8c547b05f8604be): 16411397 bytes on disk
I20260812 06:20:11.755463 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: UndoDeltaBlockGCOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":118,"lbm_reads_lt_1ms":4}
I20260812 06:20:11.755887 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be): perf score=14.095187
I20260812 06:20:11.821131 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.065s	user 0.023s	sys 0.039s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26038,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:11.821707 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be): perf score=2.188937
I20260812 06:20:11.832643 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4316,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:11.836073 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling MajorDeltaCompactionOp(736f1637c9c8409ab8c547b05f8604be): perf score=1.000000
I20260812 06:20:12.016752 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: MajorDeltaCompactionOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.180s	user 0.105s	sys 0.075s 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":441,"lbm_read_time_us":12922,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30189,"lbm_writes_lt_1ms":543,"mutex_wait_us":61,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":45568,"update_count":2500}
I20260812 06:20:12.017565 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be): perf score=14.095187
I20260812 06:20:12.067981 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.050s	user 0.038s	sys 0.011s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22666,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:12.068488 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be): perf score=2.188937
I20260812 06:20:12.088083 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.019s	user 0.007s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4872,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:12.088572 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling MajorDeltaCompactionOp(736f1637c9c8409ab8c547b05f8604be): perf score=1.000000
I20260812 06:20:12.271646 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: MajorDeltaCompactionOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.183s	user 0.118s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":399,"lbm_read_time_us":13208,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28423,"lbm_writes_lt_1ms":543,"mutex_wait_us":174,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:20:12.272336 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be): perf score=15.087375
I20260812 06:20:12.322969 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.050s	user 0.030s	sys 0.017s Metrics: {"bytes_written":16820145,"delete_count":0,"lbm_write_time_us":22227,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:20:12.323669 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be): perf score=2.188937
I20260812 06:20:12.352685 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.029s	user 0.007s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4492,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:12.353312 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be): perf score=2.188937
I20260812 06:20:12.369342 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.016s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5739,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:12.369958 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling MajorDeltaCompactionOp(736f1637c9c8409ab8c547b05f8604be): perf score=1.000000
I20260812 06:20:12.579368 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: MajorDeltaCompactionOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.209s	user 0.145s	sys 0.064s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877209,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1013,"lbm_read_time_us":16064,"lbm_reads_lt_1ms":673,"lbm_write_time_us":32861,"lbm_writes_lt_1ms":643,"mutex_wait_us":284,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":3000}
I20260812 06:20:12.580174 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be): perf score=14.095187
I20260812 06:20:12.640556 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.060s	user 0.019s	sys 0.036s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20514,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:12.641103 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be): perf score=2.188937
I20260812 06:20:12.651798 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4199,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:12.652228 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushMRSOp(736f1637c9c8409ab8c547b05f8604be): perf score=1.000000
I20260812 06:20:12.693961 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushMRSOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.042s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":278,"dirs.run_wall_time_us":1238,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1445,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:20:12.694628 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling LogGCOp(736f1637c9c8409ab8c547b05f8604be): free 120553384 bytes of WAL
I20260812 06:20:12.694860 28254 log_reader.cc:385] T 736f1637c9c8409ab8c547b05f8604be: removed 12 log segments from log reader
I20260812 06:20:12.694911 28254 log.cc:1079] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/736f1637c9c8409ab8c547b05f8604be/wal-000000003 (ops 12-16)
I20260812 06:20:12.694962 28254 log.cc:1079] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/736f1637c9c8409ab8c547b05f8604be/wal-000000004 (ops 17-21)
I20260812 06:20:12.695008 28254 log.cc:1079] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/736f1637c9c8409ab8c547b05f8604be/wal-000000005 (ops 22-26)
I20260812 06:20:12.695048 28254 log.cc:1079] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/736f1637c9c8409ab8c547b05f8604be/wal-000000006 (ops 27-31)
I20260812 06:20:12.695092 28254 log.cc:1079] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/736f1637c9c8409ab8c547b05f8604be/wal-000000007 (ops 32-36)
I20260812 06:20:12.695148 28254 log.cc:1079] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/736f1637c9c8409ab8c547b05f8604be/wal-000000008 (ops 37-41)
I20260812 06:20:12.695185 28254 log.cc:1079] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/736f1637c9c8409ab8c547b05f8604be/wal-000000009 (ops 42-46)
I20260812 06:20:12.695255 28254 log.cc:1079] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/736f1637c9c8409ab8c547b05f8604be/wal-000000010 (ops 47-50)
I20260812 06:20:12.695297 28254 log.cc:1079] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/736f1637c9c8409ab8c547b05f8604be/wal-000000011 (ops 51-55)
I20260812 06:20:12.695338 28254 log.cc:1079] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/736f1637c9c8409ab8c547b05f8604be/wal-000000012 (ops 56-60)
I20260812 06:20:12.695379 28254 log.cc:1079] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/736f1637c9c8409ab8c547b05f8604be/wal-000000013 (ops 61-64)
I20260812 06:20:12.695420 28254 log.cc:1079] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/736f1637c9c8409ab8c547b05f8604be/wal-000000014 (ops 65-69)
I20260812 06:20:12.721391 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: LogGCOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.027s	user 0.002s	sys 0.023s Metrics: {}
I20260812 06:20:12.721809 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be): perf score=2.188937
I20260812 06:20:12.738708 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.017s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4303,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:12.739238 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be): perf score=2.188937
I20260812 06:20:12.750442 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4444,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:12.751013 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling MajorDeltaCompactionOp(736f1637c9c8409ab8c547b05f8604be): perf score=1.000000
I20260812 06:20:12.987703 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: MajorDeltaCompactionOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.236s	user 0.162s	sys 0.068s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979749,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":643,"lbm_read_time_us":15374,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40590,"lbm_writes_lt_1ms":743,"mutex_wait_us":59,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3328,"thread_start_us":80,"threads_started":1,"update_count":3500}
I20260812 06:20:12.988451 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be): perf score=18.063937
I20260812 06:20:13.053866 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.065s	user 0.034s	sys 0.016s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":23948,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:13.054365 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be): perf score=2.188937
I20260812 06:20:13.065547 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.011s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4163,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:13.066200 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling UndoDeltaBlockGCOp(736f1637c9c8409ab8c547b05f8604be): 472 bytes on disk
I20260812 06:20:13.066859 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: UndoDeltaBlockGCOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":83,"lbm_reads_lt_1ms":4}
I20260812 06:20:13.067497 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling MajorDeltaCompactionOp(736f1637c9c8409ab8c547b05f8604be): perf score=1.000000
I20260812 06:20:13.271682 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: MajorDeltaCompactionOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.204s	user 0.146s	sys 0.051s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877105,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":616,"lbm_read_time_us":12952,"lbm_reads_lt_1ms":672,"lbm_write_time_us":37566,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3000}
I20260812 06:20:13.272235 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be): perf score=18.063937
I20260812 06:20:13.345496 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.073s	user 0.028s	sys 0.041s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":30000,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:13.345958 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be): perf score=3.181125
I20260812 06:20:13.359962 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.014s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4465,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:13.360464 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be): perf score=2.188937
I20260812 06:20:13.370339 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.010s	user 0.006s	sys 0.002s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3845,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:13.370929 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling MajorDeltaCompactionOp(736f1637c9c8409ab8c547b05f8604be): perf score=1.000000
I20260812 06:20:13.575420 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: MajorDeltaCompactionOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.204s	user 0.139s	sys 0.064s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979621,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":382,"lbm_read_time_us":14847,"lbm_reads_lt_1ms":773,"lbm_write_time_us":43032,"lbm_writes_lt_1ms":743,"mutex_wait_us":102,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":3500}
I20260812 06:20:13.579599 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be): perf score=15.087375
I20260812 06:20:13.644037 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.064s	user 0.036s	sys 0.016s Metrics: {"bytes_written":17435508,"delete_count":0,"lbm_write_time_us":23106,"lbm_writes_lt_1ms":428,"reinsert_count":0,"update_count":2125}
I20260812 06:20:13.644559 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be): perf score=5.165500
I20260812 06:20:13.668856 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.024s	user 0.013s	sys 0.008s Metrics: {"bytes_written":7179477,"delete_count":0,"lbm_write_time_us":9476,"lbm_writes_lt_1ms":178,"reinsert_count":0,"update_count":875}
I20260812 06:20:13.669323 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling MajorDeltaCompactionOp(736f1637c9c8409ab8c547b05f8604be): perf score=1.000000
I20260812 06:20:13.836722 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: MajorDeltaCompactionOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.167s	user 0.127s	sys 0.039s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877107,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1616,"lbm_read_time_us":11224,"lbm_reads_lt_1ms":664,"lbm_write_time_us":35235,"lbm_writes_lt_1ms":643,"mutex_wait_us":24,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":3000}
I20260812 06:20:13.837525 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be): perf score=14.095187
I20260812 06:20:13.892071 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.054s	user 0.037s	sys 0.016s Metrics: {"bytes_written":16532974,"delete_count":0,"lbm_write_time_us":23542,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":405,"mutex_wait_us":160,"reinsert_count":0,"update_count":2015}
I20260812 06:20:13.893124 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be): perf score=2.188937
I20260812 06:20:13.919157 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.026s	user 0.005s	sys 0.007s Metrics: {"bytes_written":3979584,"delete_count":0,"lbm_write_time_us":5707,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:20:13.919647 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be): perf score=2.188937
I20260812 06:20:13.929912 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3850,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:13.930339 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling MajorDeltaCompactionOp(736f1637c9c8409ab8c547b05f8604be): perf score=1.000000
I20260812 06:20:14.115093 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: MajorDeltaCompactionOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.185s	user 0.152s	sys 0.028s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877217,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":10895,"dirs.run_cpu_time_us":590,"dirs.run_wall_time_us":3556,"lbm_read_time_us":12607,"lbm_reads_lt_1ms":673,"lbm_write_time_us":37059,"lbm_writes_lt_1ms":643,"mutex_wait_us":3608,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":3000}
I20260812 06:20:14.115729 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be): perf score=14.095187
I20260812 06:20:14.169618 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.054s	user 0.028s	sys 0.023s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":26843,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:20:14.170295 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be): perf score=2.188937
I20260812 06:20:14.189991 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.019s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7408,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:14.190626 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushMRSOp(736f1637c9c8409ab8c547b05f8604be): perf score=1.000000
I20260812 06:20:14.242604 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushMRSOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.052s	user 0.026s	sys 0.005s Metrics: {"bytes_written":1357580,"cfile_init":1,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":276,"dirs.run_wall_time_us":1263,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1950,"lbm_writes_lt_1ms":44,"peak_mem_usage":0,"rows_written":33}
I20260812 06:20:14.243404 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling LogGCOp(736f1637c9c8409ab8c547b05f8604be): free 133024402 bytes of WAL
I20260812 06:20:14.243625 28254 log_reader.cc:385] T 736f1637c9c8409ab8c547b05f8604be: removed 13 log segments from log reader
I20260812 06:20:14.243669 28254 log.cc:1079] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/736f1637c9c8409ab8c547b05f8604be/wal-000000015 (ops 70-74)
I20260812 06:20:14.243718 28254 log.cc:1079] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/736f1637c9c8409ab8c547b05f8604be/wal-000000016 (ops 75-79)
I20260812 06:20:14.243763 28254 log.cc:1079] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/736f1637c9c8409ab8c547b05f8604be/wal-000000017 (ops 80-84)
I20260812 06:20:14.243808 28254 log.cc:1079] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/736f1637c9c8409ab8c547b05f8604be/wal-000000018 (ops 85-89)
I20260812 06:20:14.243845 28254 log.cc:1079] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/736f1637c9c8409ab8c547b05f8604be/wal-000000019 (ops 90-94)
I20260812 06:20:14.243911 28254 log.cc:1079] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/736f1637c9c8409ab8c547b05f8604be/wal-000000020 (ops 95-99)
I20260812 06:20:14.243947 28254 log.cc:1079] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/736f1637c9c8409ab8c547b05f8604be/wal-000000021 (ops 100-104)
I20260812 06:20:14.243985 28254 log.cc:1079] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/736f1637c9c8409ab8c547b05f8604be/wal-000000022 (ops 105-109)
I20260812 06:20:14.244027 28254 log.cc:1079] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/736f1637c9c8409ab8c547b05f8604be/wal-000000023 (ops 110-114)
I20260812 06:20:14.244067 28254 log.cc:1079] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/736f1637c9c8409ab8c547b05f8604be/wal-000000024 (ops 115-118)
I20260812 06:20:14.244112 28254 log.cc:1079] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/736f1637c9c8409ab8c547b05f8604be/wal-000000025 (ops 119-123)
I20260812 06:20:14.244155 28254 log.cc:1079] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/736f1637c9c8409ab8c547b05f8604be/wal-000000026 (ops 124-128)
I20260812 06:20:14.244195 28254 log.cc:1079] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/736f1637c9c8409ab8c547b05f8604be/wal-000000027 (ops 129-133)
I20260812 06:20:14.271692 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: LogGCOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.028s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:20:14.272078 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be): perf score=7.149875
I20260812 06:20:14.297272 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.025s	user 0.014s	sys 0.009s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":10689,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:20:14.297858 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be): perf score=2.188937
I20260812 06:20:14.313453 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.015s	user 0.006s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6120,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:14.313884 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling MajorDeltaCompactionOp(736f1637c9c8409ab8c547b05f8604be): perf score=1.000000
I20260812 06:20:14.522307 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: MajorDeltaCompactionOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.208s	user 0.172s	sys 0.036s Metrics: {"cfile_cache_miss":834,"cfile_cache_miss_bytes":37082156,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":704,"lbm_read_time_us":17200,"lbm_reads_lt_1ms":870,"lbm_write_time_us":43124,"lbm_writes_lt_1ms":843,"mutex_wait_us":46,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":14976,"thread_start_us":120,"threads_started":2,"update_count":4000}
I20260812 06:20:14.523053 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be): perf score=18.063937
I20260812 06:20:14.576339 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.053s	user 0.044s	sys 0.008s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":23709,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:14.577049 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be): perf score=2.188937
I20260812 06:20:14.604781 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.027s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6966,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:14.605492 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling MajorDeltaCompactionOp(736f1637c9c8409ab8c547b05f8604be): perf score=1.000000
I20260812 06:20:14.818835 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: MajorDeltaCompactionOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.213s	user 0.151s	sys 0.056s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877104,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":170,"lbm_read_time_us":13823,"lbm_reads_lt_1ms":664,"lbm_write_time_us":34930,"lbm_writes_lt_1ms":643,"mutex_wait_us":64,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3000}
I20260812 06:20:14.819490 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling UndoDeltaBlockGCOp(736f1637c9c8409ab8c547b05f8604be): 507 bytes on disk
I20260812 06:20:14.819948 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: UndoDeltaBlockGCOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:20:14.820842 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be): perf score=15.087375
I20260812 06:20:14.888661 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.068s	user 0.028s	sys 0.035s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":27426,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":411,"reinsert_count":0,"update_count":2050}
I20260812 06:20:14.889231 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be): perf score=6.157687
I20260812 06:20:14.910439 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.021s	user 0.015s	sys 0.003s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":8917,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:20:14.911031 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling MajorDeltaCompactionOp(736f1637c9c8409ab8c547b05f8604be): perf score=1.000000
I20260812 06:20:15.131855 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: MajorDeltaCompactionOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.221s	user 0.128s	sys 0.093s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877100,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":217,"lbm_read_time_us":14407,"lbm_reads_lt_1ms":672,"lbm_write_time_us":36113,"lbm_writes_lt_1ms":643,"mutex_wait_us":28,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":18432,"update_count":3000}
I20260812 06:20:15.132815 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be): perf score=18.063937
I20260812 06:20:15.202908 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.070s	user 0.025s	sys 0.041s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":32709,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:20:15.203510 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be): perf score=2.188937
I20260812 06:20:15.222649 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.019s	user 0.005s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5896,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:15.223143 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling MajorDeltaCompactionOp(736f1637c9c8409ab8c547b05f8604be): perf score=1.000000
I20260812 06:20:15.439719 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: MajorDeltaCompactionOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.216s	user 0.150s	sys 0.065s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877105,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1218,"lbm_read_time_us":13615,"lbm_reads_lt_1ms":664,"lbm_write_time_us":36681,"lbm_writes_lt_1ms":643,"mutex_wait_us":646,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":3000}
I20260812 06:20:15.440589 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be): perf score=18.063937
I20260812 06:20:15.495142 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.054s	user 0.034s	sys 0.016s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":23354,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:15.495741 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be): perf score=2.188937
I20260812 06:20:15.520591 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.025s	user 0.002s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5981,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:15.521039 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be): perf score=2.188937
I20260812 06:20:15.531337 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.010s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4119,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:15.531764 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling MajorDeltaCompactionOp(736f1637c9c8409ab8c547b05f8604be): perf score=1.000000
I20260812 06:20:15.762349 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: MajorDeltaCompactionOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.230s	user 0.143s	sys 0.076s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979636,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":449,"lbm_read_time_us":16827,"lbm_reads_lt_1ms":773,"lbm_write_time_us":39643,"lbm_writes_lt_1ms":743,"mutex_wait_us":279,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":17664,"update_count":3500}
I20260812 06:20:15.763064 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be): perf score=18.063937
I20260812 06:20:15.815595 27737 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.887s	user 1.841s	sys 0.178s
I20260812 06:20:15.819244 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.056s	user 0.039s	sys 0.011s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":24345,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:15.819782 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be): perf score=2.188937
I20260812 06:20:15.829739 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushDeltaMemStoresOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4236,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":500}
I20260812 06:20:15.830262 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling FlushMRSOp(736f1637c9c8409ab8c547b05f8604be): perf score=1.000000
I20260812 06:20:15.856536 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: FlushMRSOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.026s	user 0.021s	sys 0.004s Metrics: {"bytes_written":1357578,"cfile_init":1,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":233,"dirs.run_wall_time_us":1193,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1719,"lbm_writes_lt_1ms":44,"peak_mem_usage":0,"rows_written":33}
I20260812 06:20:15.857296 28366 maintenance_manager.cc:419] P 33449c4ebb0c43fab3d0aff6845583fc: Scheduling LogGCOp(736f1637c9c8409ab8c547b05f8604be): free 133024646 bytes of WAL
I20260812 06:20:15.857556 28254 log_reader.cc:385] T 736f1637c9c8409ab8c547b05f8604be: removed 13 log segments from log reader
I20260812 06:20:15.857628 28254 log.cc:1079] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/736f1637c9c8409ab8c547b05f8604be/wal-000000028 (ops 134-138)
I20260812 06:20:15.857686 28254 log.cc:1079] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/736f1637c9c8409ab8c547b05f8604be/wal-000000029 (ops 139-143)
I20260812 06:20:15.857744 28254 log.cc:1079] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/736f1637c9c8409ab8c547b05f8604be/wal-000000030 (ops 144-148)
I20260812 06:20:15.857788 28254 log.cc:1079] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/736f1637c9c8409ab8c547b05f8604be/wal-000000031 (ops 149-152)
I20260812 06:20:15.857829 28254 log.cc:1079] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/736f1637c9c8409ab8c547b05f8604be/wal-000000032 (ops 153-157)
I20260812 06:20:15.857868 28254 log.cc:1079] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/736f1637c9c8409ab8c547b05f8604be/wal-000000033 (ops 158-162)
I20260812 06:20:15.857909 28254 log.cc:1079] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/736f1637c9c8409ab8c547b05f8604be/wal-000000034 (ops 163-167)
I20260812 06:20:15.857949 28254 log.cc:1079] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/736f1637c9c8409ab8c547b05f8604be/wal-000000035 (ops 168-172)
I20260812 06:20:15.857988 28254 log.cc:1079] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/736f1637c9c8409ab8c547b05f8604be/wal-000000036 (ops 173-177)
I20260812 06:20:15.858040 28254 log.cc:1079] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/736f1637c9c8409ab8c547b05f8604be/wal-000000037 (ops 178-182)
I20260812 06:20:15.858079 28254 log.cc:1079] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/736f1637c9c8409ab8c547b05f8604be/wal-000000038 (ops 183-187)
I20260812 06:20:15.858116 28254 log.cc:1079] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/736f1637c9c8409ab8c547b05f8604be/wal-000000039 (ops 188-192)
I20260812 06:20:15.858155 28254 log.cc:1079] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: Deleting log segment in path: /tmp/dist-test-task0qiAb6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515605218210-27737-0/minicluster-data/ts-0-root/wals/736f1637c9c8409ab8c547b05f8604be/wal-000000040 (ops 193-197)
I20260812 06:20:15.870536 27737 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.054s	user 0.003s	sys 0.000s
I20260812 06:20:15.871078 27737 tablet_server.cc:179] TabletServer@127.27.22.65:0 shutting down...
I20260812 06:20:15.887181 28254 maintenance_manager.cc:643] P 33449c4ebb0c43fab3d0aff6845583fc: LogGCOp(736f1637c9c8409ab8c547b05f8604be) complete. Timing: real 0.030s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:20:15.887709 27737 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:15.887955 27737 tablet_replica.cc:333] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc: stopping tablet replica
I20260812 06:20:15.888090 27737 raft_consensus.cc:2243] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:15.888274 27737 raft_consensus.cc:2272] T 736f1637c9c8409ab8c547b05f8604be P 33449c4ebb0c43fab3d0aff6845583fc [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:15.891247 27737 tablet_server.cc:196] TabletServer@127.27.22.65:0 shutdown complete.
I20260812 06:20:15.893752 27737 master.cc:562] Master@127.27.22.126:34219 shutting down...
I20260812 06:20:15.896991 27737 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 15a62c41fb2e4195ad31365af1324fdd [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:15.897159 27737 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 15a62c41fb2e4195ad31365af1324fdd [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:15.897249 27737 tablet_replica.cc:333] T 00000000000000000000000000000000 P 15a62c41fb2e4195ad31365af1324fdd: stopping tablet replica
I20260812 06:20:15.909286 27737 master.cc:584] Master@127.27.22.126:34219 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5270 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10761 ms total)

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