[==========] 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:16:42.367236 12836 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.12.137.62:36865
I20260812 06:16:42.368312 12836 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:16:42.368937 12836 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:42.375349 12845 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:16:42.375427 12849 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:16:42.375486 12836 server_base.cc:1061] running on GCE node
W20260812 06:16:42.375653 12853 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:16:42.376156 12836 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:42.376260 12836 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:16:42.376304 12836 hybrid_clock.cc:648] HybridClock initialized: now 1786515402376302 us; error 0 us; skew 500 ppm
I20260812 06:16:42.378213 12836 webserver.cc:533] Webserver started at http://127.12.137.62:32833/ using document root <none> and password file <none>
I20260812 06:16:42.378778 12836 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:42.378855 12836 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:42.379115 12836 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:42.380818 12836 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/master-0-root/instance:
uuid: "21f8f0c3ecb64fc9affb15c5b0699f1f"
format_stamp: "Formatted at 2026-08-12 06:16:42 on dist-test-slave-vpvm"
I20260812 06:16:42.387660 12836 fs_manager.cc:696] Time spent creating directory manager: real 0.006s	user 0.004s	sys 0.004s
I20260812 06:16:42.390556 12859 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:16:42.391861 12836 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:16:42.392006 12836 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/master-0-root
uuid: "21f8f0c3ecb64fc9affb15c5b0699f1f"
format_stamp: "Formatted at 2026-08-12 06:16:42 on dist-test-slave-vpvm"
I20260812 06:16:42.392113 12836 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-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:16:42.406164 12836 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:42.406821 12836 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:16:42.406977 12836 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:42.414809 12836 rpc_server.cc:307] RPC server started. Bound to: 127.12.137.62:36865
I20260812 06:16:42.414875 12958 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.12.137.62:36865 every 8 connection(s)
I20260812 06:16:42.417189 12959 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:16:42.423014 12959 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 21f8f0c3ecb64fc9affb15c5b0699f1f: Bootstrap starting.
I20260812 06:16:42.425577 12959 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 21f8f0c3ecb64fc9affb15c5b0699f1f: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:42.426606 12959 log.cc:826] T 00000000000000000000000000000000 P 21f8f0c3ecb64fc9affb15c5b0699f1f: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:42.428521 12959 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 21f8f0c3ecb64fc9affb15c5b0699f1f: No bootstrap required, opened a new log
I20260812 06:16:42.431604 12959 raft_consensus.cc:359] T 00000000000000000000000000000000 P 21f8f0c3ecb64fc9affb15c5b0699f1f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "21f8f0c3ecb64fc9affb15c5b0699f1f" member_type: VOTER }
I20260812 06:16:42.431790 12959 raft_consensus.cc:385] T 00000000000000000000000000000000 P 21f8f0c3ecb64fc9affb15c5b0699f1f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:42.431862 12959 raft_consensus.cc:740] T 00000000000000000000000000000000 P 21f8f0c3ecb64fc9affb15c5b0699f1f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 21f8f0c3ecb64fc9affb15c5b0699f1f, State: Initialized, Role: FOLLOWER
I20260812 06:16:42.432503 12959 consensus_queue.cc:260] T 00000000000000000000000000000000 P 21f8f0c3ecb64fc9affb15c5b0699f1f [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: "21f8f0c3ecb64fc9affb15c5b0699f1f" member_type: VOTER }
I20260812 06:16:42.432667 12959 raft_consensus.cc:399] T 00000000000000000000000000000000 P 21f8f0c3ecb64fc9affb15c5b0699f1f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:42.432741 12959 raft_consensus.cc:493] T 00000000000000000000000000000000 P 21f8f0c3ecb64fc9affb15c5b0699f1f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:42.432878 12959 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 21f8f0c3ecb64fc9affb15c5b0699f1f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:42.433754 12959 raft_consensus.cc:515] T 00000000000000000000000000000000 P 21f8f0c3ecb64fc9affb15c5b0699f1f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "21f8f0c3ecb64fc9affb15c5b0699f1f" member_type: VOTER }
I20260812 06:16:42.434230 12959 leader_election.cc:304] T 00000000000000000000000000000000 P 21f8f0c3ecb64fc9affb15c5b0699f1f [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: 21f8f0c3ecb64fc9affb15c5b0699f1f; no voters: 
I20260812 06:16:42.434595 12959 leader_election.cc:290] T 00000000000000000000000000000000 P 21f8f0c3ecb64fc9affb15c5b0699f1f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:42.434717 12966 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 21f8f0c3ecb64fc9affb15c5b0699f1f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:42.434939 12966 raft_consensus.cc:697] T 00000000000000000000000000000000 P 21f8f0c3ecb64fc9affb15c5b0699f1f [term 1 LEADER]: Becoming Leader. State: Replica: 21f8f0c3ecb64fc9affb15c5b0699f1f, State: Running, Role: LEADER
I20260812 06:16:42.435348 12966 consensus_queue.cc:237] T 00000000000000000000000000000000 P 21f8f0c3ecb64fc9affb15c5b0699f1f [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: "21f8f0c3ecb64fc9affb15c5b0699f1f" member_type: VOTER }
I20260812 06:16:42.435667 12959 sys_catalog.cc:565] T 00000000000000000000000000000000 P 21f8f0c3ecb64fc9affb15c5b0699f1f [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:42.437345 12967 sys_catalog.cc:455] T 00000000000000000000000000000000 P 21f8f0c3ecb64fc9affb15c5b0699f1f [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "21f8f0c3ecb64fc9affb15c5b0699f1f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "21f8f0c3ecb64fc9affb15c5b0699f1f" member_type: VOTER } }
I20260812 06:16:42.437372 12971 sys_catalog.cc:455] T 00000000000000000000000000000000 P 21f8f0c3ecb64fc9affb15c5b0699f1f [sys.catalog]: SysCatalogTable state changed. Reason: New leader 21f8f0c3ecb64fc9affb15c5b0699f1f. Latest consensus state: current_term: 1 leader_uuid: "21f8f0c3ecb64fc9affb15c5b0699f1f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "21f8f0c3ecb64fc9affb15c5b0699f1f" member_type: VOTER } }
I20260812 06:16:42.437500 12967 sys_catalog.cc:458] T 00000000000000000000000000000000 P 21f8f0c3ecb64fc9affb15c5b0699f1f [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:42.437498 12971 sys_catalog.cc:458] T 00000000000000000000000000000000 P 21f8f0c3ecb64fc9affb15c5b0699f1f [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:42.438115 12836 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:42.438272 12986 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:42.440404 12986 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:42.444890 12986 catalog_manager.cc:1383] Generated new cluster ID: db5e02e6a9fa4ebbb4c5d23babdf9bd4
I20260812 06:16:42.444960 12986 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:42.460321 12986 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:42.461151 12986 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:42.470388 12986 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 21f8f0c3ecb64fc9affb15c5b0699f1f: Generated new TSK 0
I20260812 06:16:42.471058 12986 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:42.503170 12836 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:42.506140 12996 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:16:42.506140 12998 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:16:42.506377 12836 server_base.cc:1061] running on GCE node
W20260812 06:16:42.506378 13000 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:16:42.506664 12836 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:42.506704 12836 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:16:42.506719 12836 hybrid_clock.cc:648] HybridClock initialized: now 1786515402506719 us; error 0 us; skew 500 ppm
I20260812 06:16:42.507537 12836 webserver.cc:533] Webserver started at http://127.12.137.1:34257/ using document root <none> and password file <none>
I20260812 06:16:42.507690 12836 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:42.507745 12836 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:42.507820 12836 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:42.508198 12836 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root/instance:
uuid: "b39fe6316c5e483dae325ee0b9c01be6"
format_stamp: "Formatted at 2026-08-12 06:16:42 on dist-test-slave-vpvm"
I20260812 06:16:42.509701 12836 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.001s
I20260812 06:16:42.510733 13007 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:16:42.511009 12836 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:16:42.511080 12836 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root
uuid: "b39fe6316c5e483dae325ee0b9c01be6"
format_stamp: "Formatted at 2026-08-12 06:16:42 on dist-test-slave-vpvm"
I20260812 06:16:42.511148 12836 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-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:16:42.527184 12836 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:42.528023 12836 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:42.528514 12836 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:42.529356 12836 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:42.529407 12836 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:42.529456 12836 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:42.529486 12836 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:42.535511 12836 rpc_server.cc:307] RPC server started. Bound to: 127.12.137.1:35455
I20260812 06:16:42.535559 13122 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.12.137.1:35455 every 8 connection(s)
I20260812 06:16:42.545048 13124 heartbeater.cc:344] Connected to a master server at 127.12.137.62:36865
I20260812 06:16:42.545290 13124 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:42.545751 13124 heartbeater.cc:507] Master 127.12.137.62:36865 requested a full tablet report, sending...
I20260812 06:16:42.547190 12897 ts_manager.cc:194] Registered new tserver with Master: b39fe6316c5e483dae325ee0b9c01be6 (127.12.137.1:35455)
I20260812 06:16:42.547677 12836 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011587284s
I20260812 06:16:42.548386 12897 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:48372
I20260812 06:16:42.557886 12897 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:48378:
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:16:42.571998 13058 tablet_service.cc:1511] Processing CreateTablet for tablet c0794adb9c5c4d9fa41cec4fcabaebed (DEFAULT_TABLE table=heavy-update-compaction-test [id=9159b4bd51df475abd878cf07e982225]), partition=
I20260812 06:16:42.572515 13058 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet c0794adb9c5c4d9fa41cec4fcabaebed. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:42.574752 13140 tablet_bootstrap.cc:492] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Bootstrap starting.
I20260812 06:16:42.576119 13140 tablet_bootstrap.cc:654] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:42.577183 13140 tablet_bootstrap.cc:492] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: No bootstrap required, opened a new log
I20260812 06:16:42.577272 13140 ts_tablet_manager.cc:1403] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:16:42.577706 13140 raft_consensus.cc:359] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b39fe6316c5e483dae325ee0b9c01be6" member_type: VOTER last_known_addr { host: "127.12.137.1" port: 35455 } }
I20260812 06:16:42.577809 13140 raft_consensus.cc:385] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:42.577831 13140 raft_consensus.cc:740] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b39fe6316c5e483dae325ee0b9c01be6, State: Initialized, Role: FOLLOWER
I20260812 06:16:42.577982 13140 consensus_queue.cc:260] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6 [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: "b39fe6316c5e483dae325ee0b9c01be6" member_type: VOTER last_known_addr { host: "127.12.137.1" port: 35455 } }
I20260812 06:16:42.578074 13140 raft_consensus.cc:399] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:42.578104 13140 raft_consensus.cc:493] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:42.578150 13140 raft_consensus.cc:3060] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:42.578884 13140 raft_consensus.cc:515] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b39fe6316c5e483dae325ee0b9c01be6" member_type: VOTER last_known_addr { host: "127.12.137.1" port: 35455 } }
I20260812 06:16:42.579015 13140 leader_election.cc:304] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6 [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: b39fe6316c5e483dae325ee0b9c01be6; no voters: 
I20260812 06:16:42.579222 13140 leader_election.cc:290] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:42.579317 13142 raft_consensus.cc:2804] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:42.579519 13142 raft_consensus.cc:697] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6 [term 1 LEADER]: Becoming Leader. State: Replica: b39fe6316c5e483dae325ee0b9c01be6, State: Running, Role: LEADER
I20260812 06:16:42.579622 13140 ts_tablet_manager.cc:1434] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:16:42.579717 13142 consensus_queue.cc:237] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6 [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: "b39fe6316c5e483dae325ee0b9c01be6" member_type: VOTER last_known_addr { host: "127.12.137.1" port: 35455 } }
I20260812 06:16:42.580072 13124 heartbeater.cc:499] Master 127.12.137.62:36865 was elected leader, sending a full tablet report...
I20260812 06:16:42.582782 12897 catalog_manager.cc:5719] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6 reported cstate change: term changed from 0 to 1, leader changed from <none> to b39fe6316c5e483dae325ee0b9c01be6 (127.12.137.1). New cstate: current_term: 1 leader_uuid: "b39fe6316c5e483dae325ee0b9c01be6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b39fe6316c5e483dae325ee0b9c01be6" member_type: VOTER last_known_addr { host: "127.12.137.1" port: 35455 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:42.726310 12836 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.134s	user 0.011s	sys 0.033s
I20260812 06:16:42.786857 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushMRSOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=3.179940
I20260812 06:16:42.907366 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushMRSOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.120s	user 0.068s	sys 0.049s Metrics: {"bytes_written":4266761,"cfile_init":1,"compiler_manager_pool.queue_time_us":213,"delete_count":0,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":173,"dirs.run_wall_time_us":813,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44464,"lbm_writes_1-10_ms":13,"lbm_writes_lt_1ms":158,"peak_mem_usage":0,"reinsert_count":0,"rows_written":101,"spinlock_wait_cycles":241024,"thread_start_us":106,"threads_started":1,"update_count":520}
I20260812 06:16:42.908808 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=2.188937
I20260812 06:16:42.937849 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.029s	user 0.008s	sys 0.020s Metrics: {"bytes_written":3528305,"delete_count":0,"lbm_write_time_us":18392,"lbm_writes_lt_1ms":89,"reinsert_count":0,"update_count":430}
I20260812 06:16:42.938369 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling UndoDeltaBlockGCOp(c0794adb9c5c4d9fa41cec4fcabaebed): 411733 bytes on disk
I20260812 06:16:42.938992 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: UndoDeltaBlockGCOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4}
I20260812 06:16:42.939452 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=1.000000
I20260812 06:16:43.040853 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.101s	user 0.079s	sys 0.019s Metrics: {"cfile_cache_miss":222,"cfile_cache_miss_bytes":11934305,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":901,"lbm_read_time_us":5224,"lbm_reads_lt_1ms":250,"lbm_write_time_us":15933,"lbm_writes_lt_1ms":233,"peak_mem_usage":24385450,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":307,"threads_started":5,"update_count":950}
I20260812 06:16:43.041343 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=7.149875
I20260812 06:16:43.064465 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.023s	user 0.012s	sys 0.008s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":9374,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:43.065012 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=2.188937
I20260812 06:16:43.081542 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.016s	user 0.011s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5833,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:43.082043 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=1.000000
I20260812 06:16:43.197871 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.116s	user 0.087s	sys 0.021s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16446961,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":231,"lbm_read_time_us":7841,"lbm_reads_lt_1ms":368,"lbm_write_time_us":19243,"lbm_writes_lt_1ms":343,"mutex_wait_us":29,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":67840,"update_count":1500}
I20260812 06:16:43.198401 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=10.126437
I20260812 06:16:43.230160 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.031s	user 0.022s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12632,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:43.230684 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=1.000000
I20260812 06:16:43.331146 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.100s	user 0.080s	sys 0.020s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16446852,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":337,"lbm_read_time_us":5580,"lbm_reads_lt_1ms":363,"lbm_write_time_us":20041,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":1500}
I20260812 06:16:43.331878 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=10.126437
I20260812 06:16:43.374493 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.042s	user 0.014s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13218,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:43.375036 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=2.188937
I20260812 06:16:43.385365 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3613,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.386023 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=1.000000
I20260812 06:16:43.508279 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.122s	user 0.087s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20549382,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":555,"lbm_read_time_us":7623,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22895,"lbm_writes_lt_1ms":443,"mutex_wait_us":276,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":28672,"update_count":2000}
I20260812 06:16:43.508817 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=10.126437
I20260812 06:16:43.553056 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.044s	user 0.016s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14975,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:43.553627 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=2.188937
I20260812 06:16:43.563772 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3486,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.564329 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=1.000000
I20260812 06:16:43.682268 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.118s	user 0.089s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20549383,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":668,"lbm_read_time_us":8921,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21855,"lbm_writes_lt_1ms":443,"mutex_wait_us":321,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":46464,"update_count":2000}
I20260812 06:16:43.682817 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=10.126437
I20260812 06:16:43.720248 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.037s	user 0.030s	sys 0.000s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14103,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:43.720849 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=2.188937
I20260812 06:16:43.731168 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3633,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.731734 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=1.000000
I20260812 06:16:43.854712 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.123s	user 0.099s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20549382,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":499,"lbm_read_time_us":7777,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24778,"lbm_writes_lt_1ms":443,"mutex_wait_us":274,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":2000}
I20260812 06:16:43.855276 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=10.126437
I20260812 06:16:43.905802 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.050s	user 0.024s	sys 0.010s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12846,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":1500}
I20260812 06:16:43.906527 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=2.188937
I20260812 06:16:43.924633 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.018s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6015,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.925364 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=1.000000
I20260812 06:16:44.065762 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.140s	user 0.088s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20549382,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":145,"lbm_read_time_us":10197,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22216,"lbm_writes_lt_1ms":443,"mutex_wait_us":63,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:16:44.066335 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=10.126437
I20260812 06:16:44.108902 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.042s	user 0.010s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13884,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:44.109457 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=2.188937
I20260812 06:16:44.120079 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3845,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.120903 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=1.000000
I20260812 06:16:44.243333 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.122s	user 0.101s	sys 0.021s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20549382,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":331,"lbm_read_time_us":9286,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22334,"lbm_writes_lt_1ms":443,"mutex_wait_us":64,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:16:44.243875 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=10.126437
I20260812 06:16:44.284353 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.040s	user 0.012s	sys 0.018s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16119,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:44.284976 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=2.188937
I20260812 06:16:44.300874 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.016s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5736,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.301582 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushMRSOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=1.000000
I20260812 06:16:44.330094 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushMRSOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.028s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":271,"dirs.run_wall_time_us":1195,"drs_written":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1755,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:44.330947 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling LogGCOp(c0794adb9c5c4d9fa41cec4fcabaebed): free 129279350 bytes of WAL
I20260812 06:16:44.331274 13017 log_reader.cc:385] T c0794adb9c5c4d9fa41cec4fcabaebed: removed 13 log segments from log reader
I20260812 06:16:44.331331 13017 log.cc:1079] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/c0794adb9c5c4d9fa41cec4fcabaebed/wal-000000001 (ops 1-6)
I20260812 06:16:44.331377 13017 log.cc:1079] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/c0794adb9c5c4d9fa41cec4fcabaebed/wal-000000002 (ops 7-11)
I20260812 06:16:44.331413 13017 log.cc:1079] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/c0794adb9c5c4d9fa41cec4fcabaebed/wal-000000003 (ops 12-16)
I20260812 06:16:44.331430 13017 log.cc:1079] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/c0794adb9c5c4d9fa41cec4fcabaebed/wal-000000004 (ops 17-20)
I20260812 06:16:44.331461 13017 log.cc:1079] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/c0794adb9c5c4d9fa41cec4fcabaebed/wal-000000005 (ops 21-25)
I20260812 06:16:44.331503 13017 log.cc:1079] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/c0794adb9c5c4d9fa41cec4fcabaebed/wal-000000006 (ops 26-30)
I20260812 06:16:44.331523 13017 log.cc:1079] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/c0794adb9c5c4d9fa41cec4fcabaebed/wal-000000007 (ops 31-35)
I20260812 06:16:44.331554 13017 log.cc:1079] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/c0794adb9c5c4d9fa41cec4fcabaebed/wal-000000008 (ops 36-40)
I20260812 06:16:44.331586 13017 log.cc:1079] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/c0794adb9c5c4d9fa41cec4fcabaebed/wal-000000009 (ops 41-45)
I20260812 06:16:44.331617 13017 log.cc:1079] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/c0794adb9c5c4d9fa41cec4fcabaebed/wal-000000010 (ops 46-50)
I20260812 06:16:44.331647 13017 log.cc:1079] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/c0794adb9c5c4d9fa41cec4fcabaebed/wal-000000011 (ops 51-54)
I20260812 06:16:44.331677 13017 log.cc:1079] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/c0794adb9c5c4d9fa41cec4fcabaebed/wal-000000012 (ops 55-59)
I20260812 06:16:44.331709 13017 log.cc:1079] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/c0794adb9c5c4d9fa41cec4fcabaebed/wal-000000013 (ops 60-64)
I20260812 06:16:44.354533 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: LogGCOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.023s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:16:44.354929 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling UndoDeltaBlockGCOp(c0794adb9c5c4d9fa41cec4fcabaebed): 482 bytes on disk
I20260812 06:16:44.355356 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: UndoDeltaBlockGCOp(c0794adb9c5c4d9fa41cec4fcabaebed) 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:16:44.355832 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=3.181125
I20260812 06:16:44.368510 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.013s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4396,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:44.369035 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=2.188937
I20260812 06:16:44.383386 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4845,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:44.384014 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=1.000000
I20260812 06:16:44.560889 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.177s	user 0.137s	sys 0.032s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28754435,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":644,"lbm_read_time_us":11017,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33664,"lbm_writes_lt_1ms":643,"mutex_wait_us":61,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":76,"threads_started":1,"update_count":3000}
I20260812 06:16:44.561499 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=14.095187
I20260812 06:16:44.608556 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.047s	user 0.027s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17244,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:44.609195 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=2.188937
I20260812 06:16:44.625676 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6104,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.626298 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=1.000000
I20260812 06:16:44.775156 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.149s	user 0.114s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24651793,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":773,"lbm_read_time_us":9335,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28729,"lbm_writes_lt_1ms":543,"mutex_wait_us":509,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":36608,"update_count":2500}
I20260812 06:16:44.775836 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=12.110812
I20260812 06:16:44.812604 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.037s	user 0.020s	sys 0.014s Metrics: {"bytes_written":13784349,"delete_count":0,"lbm_write_time_us":15130,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":338,"reinsert_count":0,"update_count":1680}
I20260812 06:16:44.813560 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=1.196750
I20260812 06:16:44.835376 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.022s	user 0.010s	sys 0.000s Metrics: {"bytes_written":2625754,"delete_count":0,"lbm_write_time_us":4249,"lbm_writes_lt_1ms":67,"reinsert_count":0,"update_count":320}
I20260812 06:16:44.835991 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=2.188937
I20260812 06:16:44.851356 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5537,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.851933 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=1.000000
I20260812 06:16:45.019884 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.168s	user 0.114s	sys 0.046s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24651867,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":251,"lbm_read_time_us":11400,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27803,"lbm_writes_lt_1ms":543,"mutex_wait_us":31,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17664,"update_count":2500}
I20260812 06:16:45.020587 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=14.095187
I20260812 06:16:45.081151 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.060s	user 0.032s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":27524,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:45.081667 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=2.188937
I20260812 06:16:45.091751 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3665,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:45.092252 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=1.000000
I20260812 06:16:45.278453 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.185s	user 0.137s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24651793,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":212,"lbm_read_time_us":12569,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32233,"lbm_writes_lt_1ms":543,"mutex_wait_us":53,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":2500}
I20260812 06:16:45.279016 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=14.095187
I20260812 06:16:45.331874 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.053s	user 0.018s	sys 0.032s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":20159,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:16:45.332487 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=2.188937
I20260812 06:16:45.343024 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3971,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:45.343514 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=1.000000
I20260812 06:16:45.506122 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.162s	user 0.126s	sys 0.031s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24651791,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":297,"lbm_read_time_us":11334,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25537,"lbm_writes_lt_1ms":543,"mutex_wait_us":31,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":2500}
I20260812 06:16:45.506826 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=11.118625
I20260812 06:16:45.545209 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.038s	user 0.014s	sys 0.021s Metrics: {"bytes_written":12717738,"delete_count":0,"lbm_write_time_us":16402,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:45.546397 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=2.188937
I20260812 06:16:45.576575 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.027s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4692,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:45.577095 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=2.188937
I20260812 06:16:45.587647 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3947,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:45.588196 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=1.000000
I20260812 06:16:45.754253 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.166s	user 0.110s	sys 0.045s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24651907,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1358,"lbm_read_time_us":11653,"lbm_reads_lt_1ms":573,"lbm_write_time_us":26569,"lbm_writes_lt_1ms":543,"mutex_wait_us":48,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2500}
I20260812 06:16:45.754873 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=14.095187
I20260812 06:16:45.802544 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.048s	user 0.029s	sys 0.013s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":18373,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:45.803094 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=2.188937
I20260812 06:16:45.821934 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.019s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4182,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:45.822620 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushMRSOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=1.000000
I20260812 06:16:45.859339 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushMRSOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.037s	user 0.027s	sys 0.005s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":231,"dirs.run_wall_time_us":1251,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1665,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:16:45.860195 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling LogGCOp(c0794adb9c5c4d9fa41cec4fcabaebed): free 140432336 bytes of WAL
I20260812 06:16:45.860472 13017 log_reader.cc:385] T c0794adb9c5c4d9fa41cec4fcabaebed: removed 14 log segments from log reader
I20260812 06:16:45.860525 13017 log.cc:1079] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/c0794adb9c5c4d9fa41cec4fcabaebed/wal-000000014 (ops 65-69)
I20260812 06:16:45.860561 13017 log.cc:1079] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/c0794adb9c5c4d9fa41cec4fcabaebed/wal-000000015 (ops 70-74)
I20260812 06:16:45.860594 13017 log.cc:1079] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/c0794adb9c5c4d9fa41cec4fcabaebed/wal-000000016 (ops 75-79)
I20260812 06:16:45.860625 13017 log.cc:1079] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/c0794adb9c5c4d9fa41cec4fcabaebed/wal-000000017 (ops 80-84)
I20260812 06:16:45.860656 13017 log.cc:1079] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/c0794adb9c5c4d9fa41cec4fcabaebed/wal-000000018 (ops 85-88)
I20260812 06:16:45.860687 13017 log.cc:1079] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/c0794adb9c5c4d9fa41cec4fcabaebed/wal-000000019 (ops 89-93)
I20260812 06:16:45.860720 13017 log.cc:1079] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/c0794adb9c5c4d9fa41cec4fcabaebed/wal-000000020 (ops 94-98)
I20260812 06:16:45.860751 13017 log.cc:1079] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/c0794adb9c5c4d9fa41cec4fcabaebed/wal-000000021 (ops 99-102)
I20260812 06:16:45.860782 13017 log.cc:1079] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/c0794adb9c5c4d9fa41cec4fcabaebed/wal-000000022 (ops 103-107)
I20260812 06:16:45.860814 13017 log.cc:1079] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/c0794adb9c5c4d9fa41cec4fcabaebed/wal-000000023 (ops 108-112)
I20260812 06:16:45.860846 13017 log.cc:1079] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/c0794adb9c5c4d9fa41cec4fcabaebed/wal-000000024 (ops 113-116)
I20260812 06:16:45.860878 13017 log.cc:1079] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/c0794adb9c5c4d9fa41cec4fcabaebed/wal-000000025 (ops 117-121)
I20260812 06:16:45.860910 13017 log.cc:1079] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/c0794adb9c5c4d9fa41cec4fcabaebed/wal-000000026 (ops 122-126)
I20260812 06:16:45.860942 13017 log.cc:1079] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/c0794adb9c5c4d9fa41cec4fcabaebed/wal-000000027 (ops 127-130)
I20260812 06:16:45.886428 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: LogGCOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.026s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:16:45.886930 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling UndoDeltaBlockGCOp(c0794adb9c5c4d9fa41cec4fcabaebed): 493 bytes on disk
I20260812 06:16:45.887414 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: UndoDeltaBlockGCOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4}
I20260812 06:16:45.887995 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=3.181125
I20260812 06:16:45.909855 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.022s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6716,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:45.910395 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=2.188937
I20260812 06:16:45.920717 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3601,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:45.921249 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=1.000000
I20260812 06:16:46.124221 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.203s	user 0.131s	sys 0.068s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32856848,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1352,"lbm_read_time_us":13721,"lbm_reads_lt_1ms":774,"lbm_write_time_us":33026,"lbm_writes_lt_1ms":743,"mutex_wait_us":360,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":16384,"thread_start_us":75,"threads_started":1,"update_count":3500}
I20260812 06:16:46.125244 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=16.079562
I20260812 06:16:46.190872 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.065s	user 0.030s	sys 0.020s Metrics: {"bytes_written":17968822,"delete_count":0,"lbm_write_time_us":22695,"lbm_writes_lt_1ms":441,"reinsert_count":0,"update_count":2190}
I20260812 06:16:46.191497 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=5.165500
I20260812 06:16:46.215363 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.024s	user 0.012s	sys 0.005s Metrics: {"bytes_written":6646165,"delete_count":0,"lbm_write_time_us":7523,"lbm_writes_lt_1ms":165,"reinsert_count":0,"update_count":810}
I20260812 06:16:46.215895 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=1.000000
I20260812 06:16:46.426374 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.210s	user 0.145s	sys 0.053s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28754214,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":631,"lbm_read_time_us":13810,"lbm_reads_lt_1ms":664,"lbm_write_time_us":32431,"lbm_writes_lt_1ms":643,"mutex_wait_us":328,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":3000}
I20260812 06:16:46.426914 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=18.063937
I20260812 06:16:46.487876 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.061s	user 0.049s	sys 0.009s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":27264,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:16:46.488468 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=2.188937
I20260812 06:16:46.504513 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":5967,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.505117 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=1.000000
I20260812 06:16:46.687345 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.182s	user 0.110s	sys 0.072s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28754211,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":681,"lbm_read_time_us":12893,"lbm_reads_lt_1ms":672,"lbm_write_time_us":32698,"lbm_writes_lt_1ms":643,"mutex_wait_us":265,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":3000}
I20260812 06:16:46.687997 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=14.095187
I20260812 06:16:46.746824 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.059s	user 0.022s	sys 0.024s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":20098,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:46.747426 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=2.188937
I20260812 06:16:46.758137 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.010s	user 0.010s	sys 0.000s 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:16:46.758621 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=1.000000
I20260812 06:16:46.927837 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.169s	user 0.127s	sys 0.031s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24651791,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":625,"lbm_read_time_us":10609,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27950,"lbm_writes_lt_1ms":543,"mutex_wait_us":51,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:46.928375 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=14.095187
I20260812 06:16:46.983464 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.055s	user 0.027s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19097,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:46.984123 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=2.188937
I20260812 06:16:46.999236 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5781,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.999723 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=1.000000
I20260812 06:16:47.152827 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.153s	user 0.093s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24651794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":819,"lbm_read_time_us":11829,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25021,"lbm_writes_lt_1ms":543,"mutex_wait_us":66,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:16:47.153478 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=10.126437
I20260812 06:16:47.193166 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.039s	user 0.024s	sys 0.010s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15546,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:47.193766 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=2.188937
I20260812 06:16:47.210682 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.017s	user 0.008s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6317,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:47.211201 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushMRSOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=1.000000
I20260812 06:16:47.241878 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushMRSOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":51,"dirs.run_cpu_time_us":211,"dirs.run_wall_time_us":1315,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1506,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:16:47.242697 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling LogGCOp(c0794adb9c5c4d9fa41cec4fcabaebed): free 108535691 bytes of WAL
I20260812 06:16:47.242985 13017 log_reader.cc:385] T c0794adb9c5c4d9fa41cec4fcabaebed: removed 11 log segments from log reader
I20260812 06:16:47.243041 13017 log.cc:1079] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/c0794adb9c5c4d9fa41cec4fcabaebed/wal-000000028 (ops 131-135)
I20260812 06:16:47.243083 13017 log.cc:1079] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/c0794adb9c5c4d9fa41cec4fcabaebed/wal-000000029 (ops 136-140)
I20260812 06:16:47.243115 13017 log.cc:1079] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/c0794adb9c5c4d9fa41cec4fcabaebed/wal-000000030 (ops 141-145)
I20260812 06:16:47.243161 13017 log.cc:1079] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/c0794adb9c5c4d9fa41cec4fcabaebed/wal-000000031 (ops 146-150)
I20260812 06:16:47.243197 13017 log.cc:1079] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/c0794adb9c5c4d9fa41cec4fcabaebed/wal-000000032 (ops 151-155)
I20260812 06:16:47.243223 13017 log.cc:1079] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/c0794adb9c5c4d9fa41cec4fcabaebed/wal-000000033 (ops 156-160)
I20260812 06:16:47.243260 13017 log.cc:1079] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/c0794adb9c5c4d9fa41cec4fcabaebed/wal-000000034 (ops 161-164)
I20260812 06:16:47.243296 13017 log.cc:1079] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/c0794adb9c5c4d9fa41cec4fcabaebed/wal-000000035 (ops 165-169)
I20260812 06:16:47.243327 13017 log.cc:1079] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/c0794adb9c5c4d9fa41cec4fcabaebed/wal-000000036 (ops 170-174)
I20260812 06:16:47.243357 13017 log.cc:1079] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/c0794adb9c5c4d9fa41cec4fcabaebed/wal-000000037 (ops 175-178)
I20260812 06:16:47.243389 13017 log.cc:1079] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/c0794adb9c5c4d9fa41cec4fcabaebed/wal-000000038 (ops 179-183)
I20260812 06:16:47.261572 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: LogGCOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.019s	user 0.000s	sys 0.015s Metrics: {}
I20260812 06:16:47.262149 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=2.188937
I20260812 06:16:47.283469 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.021s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5930,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:47.283963 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling LogGCOp(c0794adb9c5c4d9fa41cec4fcabaebed): free 8767143 bytes of WAL
I20260812 06:16:47.284188 13017 log_reader.cc:385] T c0794adb9c5c4d9fa41cec4fcabaebed: removed 1 log segments from log reader
I20260812 06:16:47.284237 13017 log.cc:1079] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/c0794adb9c5c4d9fa41cec4fcabaebed/wal-000000039 (ops 184-188)
I20260812 06:16:47.285583 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: LogGCOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:16:47.285912 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=2.188937
I20260812 06:16:47.296216 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3499,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:47.296821 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling UndoDeltaBlockGCOp(c0794adb9c5c4d9fa41cec4fcabaebed): 460 bytes on disk
I20260812 06:16:47.297240 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: UndoDeltaBlockGCOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:16:47.297763 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=1.000000
I20260812 06:16:47.507967 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.210s	user 0.139s	sys 0.068s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28754444,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":4348,"lbm_read_time_us":12983,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35168,"lbm_writes_lt_1ms":643,"mutex_wait_us":3453,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":87,"threads_started":1,"update_count":3000}
I20260812 06:16:47.508653 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=14.095187
I20260812 06:16:47.552255 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.043s	user 0.025s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18960,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:47.552878 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=2.188937
I20260812 06:16:47.568782 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: FlushDeltaMemStoresOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5846,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:47.569336 13125 maintenance_manager.cc:419] P b39fe6316c5e483dae325ee0b9c01be6: Scheduling MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed): perf score=1.000000
I20260812 06:16:47.597322 12836 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.871s	user 1.760s	sys 0.115s
I20260812 06:16:47.667095 12836 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.069s	user 0.003s	sys 0.000s
I20260812 06:16:47.667913 12836 tablet_server.cc:179] TabletServer@127.12.137.1:0 shutting down...
I20260812 06:16:47.705636 13017 maintenance_manager.cc:643] P b39fe6316c5e483dae325ee0b9c01be6: MajorDeltaCompactionOp(c0794adb9c5c4d9fa41cec4fcabaebed) complete. Timing: real 0.136s	user 0.084s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24651795,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":764,"lbm_read_time_us":10538,"lbm_reads_lt_1ms":568,"lbm_write_time_us":22518,"lbm_writes_lt_1ms":543,"mutex_wait_us":290,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":40320,"update_count":2500}
I20260812 06:16:47.706259 12836 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:47.706684 12836 tablet_replica.cc:333] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6: stopping tablet replica
I20260812 06:16:47.706907 12836 raft_consensus.cc:2243] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:47.707132 12836 raft_consensus.cc:2272] T c0794adb9c5c4d9fa41cec4fcabaebed P b39fe6316c5e483dae325ee0b9c01be6 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:47.722900 12836 tablet_server.cc:196] TabletServer@127.12.137.1:0 shutdown complete.
I20260812 06:16:47.751478 12836 master.cc:562] Master@127.12.137.62:36865 shutting down...
I20260812 06:16:47.754652 12836 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 21f8f0c3ecb64fc9affb15c5b0699f1f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:47.754832 12836 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 21f8f0c3ecb64fc9affb15c5b0699f1f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:47.754908 12836 tablet_replica.cc:333] T 00000000000000000000000000000000 P 21f8f0c3ecb64fc9affb15c5b0699f1f: stopping tablet replica
I20260812 06:16:47.767192 12836 master.cc:584] Master@127.12.137.62:36865 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5471 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:16:47.848810 12836 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.12.137.62:43725
I20260812 06:16:47.849222 12836 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:47.851187 13175 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:16:47.851287 12836 server_base.cc:1061] running on GCE node
W20260812 06:16:47.851336 13176 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:16:47.851363 13179 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:16:47.851598 12836 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:47.851646 12836 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:16:47.851661 12836 hybrid_clock.cc:648] HybridClock initialized: now 1786515407851661 us; error 0 us; skew 500 ppm
I20260812 06:16:47.852386 12836 webserver.cc:533] Webserver started at http://127.12.137.62:36513/ using document root <none> and password file <none>
I20260812 06:16:47.852541 12836 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:47.852591 12836 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:47.852672 12836 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:47.853055 12836 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/master-0-root/instance:
uuid: "2cef0dde49c74dd096afbf7d7aae5e96"
format_stamp: "Formatted at 2026-08-12 06:16:47 on dist-test-slave-vpvm"
I20260812 06:16:47.854632 12836 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:47.855527 13186 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:16:47.855747 12836 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:47.855816 12836 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/master-0-root
uuid: "2cef0dde49c74dd096afbf7d7aae5e96"
format_stamp: "Formatted at 2026-08-12 06:16:47 on dist-test-slave-vpvm"
I20260812 06:16:47.855887 12836 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-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:16:47.872797 12836 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:47.873229 12836 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:47.877498 12836 rpc_server.cc:307] RPC server started. Bound to: 127.12.137.62:43725
I20260812 06:16:47.878507 13268 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.12.137.62:43725 every 8 connection(s)
I20260812 06:16:47.881582 13270 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:16:47.883546 13270 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 2cef0dde49c74dd096afbf7d7aae5e96: Bootstrap starting.
I20260812 06:16:47.884380 13270 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 2cef0dde49c74dd096afbf7d7aae5e96: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:47.885470 13270 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 2cef0dde49c74dd096afbf7d7aae5e96: No bootstrap required, opened a new log
I20260812 06:16:47.885922 13270 raft_consensus.cc:359] T 00000000000000000000000000000000 P 2cef0dde49c74dd096afbf7d7aae5e96 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2cef0dde49c74dd096afbf7d7aae5e96" member_type: VOTER }
I20260812 06:16:47.886060 13270 raft_consensus.cc:385] T 00000000000000000000000000000000 P 2cef0dde49c74dd096afbf7d7aae5e96 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:47.886087 13270 raft_consensus.cc:740] T 00000000000000000000000000000000 P 2cef0dde49c74dd096afbf7d7aae5e96 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 2cef0dde49c74dd096afbf7d7aae5e96, State: Initialized, Role: FOLLOWER
I20260812 06:16:47.886237 13270 consensus_queue.cc:260] T 00000000000000000000000000000000 P 2cef0dde49c74dd096afbf7d7aae5e96 [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: "2cef0dde49c74dd096afbf7d7aae5e96" member_type: VOTER }
I20260812 06:16:47.886309 13270 raft_consensus.cc:399] T 00000000000000000000000000000000 P 2cef0dde49c74dd096afbf7d7aae5e96 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:47.886348 13270 raft_consensus.cc:493] T 00000000000000000000000000000000 P 2cef0dde49c74dd096afbf7d7aae5e96 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:47.886399 13270 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 2cef0dde49c74dd096afbf7d7aae5e96 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:47.887106 13270 raft_consensus.cc:515] T 00000000000000000000000000000000 P 2cef0dde49c74dd096afbf7d7aae5e96 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2cef0dde49c74dd096afbf7d7aae5e96" member_type: VOTER }
I20260812 06:16:47.887234 13270 leader_election.cc:304] T 00000000000000000000000000000000 P 2cef0dde49c74dd096afbf7d7aae5e96 [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: 2cef0dde49c74dd096afbf7d7aae5e96; no voters: 
I20260812 06:16:47.887539 13270 leader_election.cc:290] T 00000000000000000000000000000000 P 2cef0dde49c74dd096afbf7d7aae5e96 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:47.887665 13274 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 2cef0dde49c74dd096afbf7d7aae5e96 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:47.887895 13274 raft_consensus.cc:697] T 00000000000000000000000000000000 P 2cef0dde49c74dd096afbf7d7aae5e96 [term 1 LEADER]: Becoming Leader. State: Replica: 2cef0dde49c74dd096afbf7d7aae5e96, State: Running, Role: LEADER
I20260812 06:16:47.888053 13270 sys_catalog.cc:565] T 00000000000000000000000000000000 P 2cef0dde49c74dd096afbf7d7aae5e96 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:47.888055 13274 consensus_queue.cc:237] T 00000000000000000000000000000000 P 2cef0dde49c74dd096afbf7d7aae5e96 [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: "2cef0dde49c74dd096afbf7d7aae5e96" member_type: VOTER }
I20260812 06:16:47.888536 13275 sys_catalog.cc:455] T 00000000000000000000000000000000 P 2cef0dde49c74dd096afbf7d7aae5e96 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "2cef0dde49c74dd096afbf7d7aae5e96" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2cef0dde49c74dd096afbf7d7aae5e96" member_type: VOTER } }
I20260812 06:16:47.888669 13275 sys_catalog.cc:458] T 00000000000000000000000000000000 P 2cef0dde49c74dd096afbf7d7aae5e96 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:47.888557 13277 sys_catalog.cc:455] T 00000000000000000000000000000000 P 2cef0dde49c74dd096afbf7d7aae5e96 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 2cef0dde49c74dd096afbf7d7aae5e96. Latest consensus state: current_term: 1 leader_uuid: "2cef0dde49c74dd096afbf7d7aae5e96" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2cef0dde49c74dd096afbf7d7aae5e96" member_type: VOTER } }
I20260812 06:16:47.888906 13277 sys_catalog.cc:458] T 00000000000000000000000000000000 P 2cef0dde49c74dd096afbf7d7aae5e96 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:47.888922 13286 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:47.889878 13286 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:47.890250 12836 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:47.891842 13286 catalog_manager.cc:1383] Generated new cluster ID: 86ec9e46a4a846c0acee8fa7e9b6eb7b
I20260812 06:16:47.891907 13286 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:47.908095 13286 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:47.908694 13286 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:47.917695 13286 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 2cef0dde49c74dd096afbf7d7aae5e96: Generated new TSK 0
I20260812 06:16:47.917903 13286 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:47.922801 12836 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:47.924887 13309 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:16:47.925001 12836 server_base.cc:1061] running on GCE node
W20260812 06:16:47.925024 13310 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:16:47.925042 13312 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:16:47.925338 12836 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:47.925386 12836 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:16:47.925402 12836 hybrid_clock.cc:648] HybridClock initialized: now 1786515407925402 us; error 0 us; skew 500 ppm
I20260812 06:16:47.926259 12836 webserver.cc:533] Webserver started at http://127.12.137.1:36443/ using document root <none> and password file <none>
I20260812 06:16:47.926421 12836 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:47.926476 12836 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:47.926554 12836 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:47.926934 12836 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root/instance:
uuid: "47e896ccf2e94a76bb7bbcbbc4f342b6"
format_stamp: "Formatted at 2026-08-12 06:16:47 on dist-test-slave-vpvm"
I20260812 06:16:47.928432 12836 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:47.929301 13322 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:16:47.929538 12836 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:47.929611 12836 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root
uuid: "47e896ccf2e94a76bb7bbcbbc4f342b6"
format_stamp: "Formatted at 2026-08-12 06:16:47 on dist-test-slave-vpvm"
I20260812 06:16:47.929680 12836 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-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:16:47.937656 12836 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:47.938115 12836 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:47.938426 12836 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:47.938917 12836 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:47.938957 12836 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:47.939002 12836 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:47.939031 12836 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:47.943368 12836 rpc_server.cc:307] RPC server started. Bound to: 127.12.137.1:40793
I20260812 06:16:47.944005 13435 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.12.137.1:40793 every 8 connection(s)
I20260812 06:16:47.948323 13436 heartbeater.cc:344] Connected to a master server at 127.12.137.62:43725
I20260812 06:16:47.948438 13436 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:47.948693 13436 heartbeater.cc:507] Master 127.12.137.62:43725 requested a full tablet report, sending...
I20260812 06:16:47.949384 13213 ts_manager.cc:194] Registered new tserver with Master: 47e896ccf2e94a76bb7bbcbbc4f342b6 (127.12.137.1:40793)
I20260812 06:16:47.949554 12836 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.00555338s
I20260812 06:16:47.950314 13213 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:36644
I20260812 06:16:47.956643 13213 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:36650:
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:16:47.965615 13362 tablet_service.cc:1511] Processing CreateTablet for tablet 02140135c03a4353ade8832502e77527 (DEFAULT_TABLE table=heavy-update-compaction-test [id=f179dc6fb6af4bd8afdc48046d5b24da]), partition=
I20260812 06:16:47.965907 13362 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 02140135c03a4353ade8832502e77527. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:47.968021 13457 tablet_bootstrap.cc:492] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Bootstrap starting.
I20260812 06:16:47.969081 13457 tablet_bootstrap.cc:654] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:47.970183 13457 tablet_bootstrap.cc:492] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: No bootstrap required, opened a new log
I20260812 06:16:47.970264 13457 ts_tablet_manager.cc:1403] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:47.970803 13457 raft_consensus.cc:359] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "47e896ccf2e94a76bb7bbcbbc4f342b6" member_type: VOTER last_known_addr { host: "127.12.137.1" port: 40793 } }
I20260812 06:16:47.970917 13457 raft_consensus.cc:385] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:47.970958 13457 raft_consensus.cc:740] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 47e896ccf2e94a76bb7bbcbbc4f342b6, State: Initialized, Role: FOLLOWER
I20260812 06:16:47.971127 13457 consensus_queue.cc:260] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6 [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: "47e896ccf2e94a76bb7bbcbbc4f342b6" member_type: VOTER last_known_addr { host: "127.12.137.1" port: 40793 } }
I20260812 06:16:47.971235 13457 raft_consensus.cc:399] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:47.971274 13457 raft_consensus.cc:493] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:47.971323 13457 raft_consensus.cc:3060] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:47.972067 13457 raft_consensus.cc:515] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "47e896ccf2e94a76bb7bbcbbc4f342b6" member_type: VOTER last_known_addr { host: "127.12.137.1" port: 40793 } }
I20260812 06:16:47.972198 13457 leader_election.cc:304] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6 [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: 47e896ccf2e94a76bb7bbcbbc4f342b6; no voters: 
I20260812 06:16:47.972395 13457 leader_election.cc:290] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:47.972550 13459 raft_consensus.cc:2804] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:47.972756 13457 ts_tablet_manager.cc:1434] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:16:47.972790 13459 raft_consensus.cc:697] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6 [term 1 LEADER]: Becoming Leader. State: Replica: 47e896ccf2e94a76bb7bbcbbc4f342b6, State: Running, Role: LEADER
I20260812 06:16:47.972819 13436 heartbeater.cc:499] Master 127.12.137.62:43725 was elected leader, sending a full tablet report...
I20260812 06:16:47.973001 13459 consensus_queue.cc:237] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6 [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: "47e896ccf2e94a76bb7bbcbbc4f342b6" member_type: VOTER last_known_addr { host: "127.12.137.1" port: 40793 } }
I20260812 06:16:47.974301 13213 catalog_manager.cc:5719] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6 reported cstate change: term changed from 0 to 1, leader changed from <none> to 47e896ccf2e94a76bb7bbcbbc4f342b6 (127.12.137.1). New cstate: current_term: 1 leader_uuid: "47e896ccf2e94a76bb7bbcbbc4f342b6" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "47e896ccf2e94a76bb7bbcbbc4f342b6" member_type: VOTER last_known_addr { host: "127.12.137.1" port: 40793 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:48.033938 12836 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.013s	sys 0.010s
I20260812 06:16:48.194643 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushMRSOp(02140135c03a4353ade8832502e77527): perf score=23.023690
I20260812 06:16:48.357501 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushMRSOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.163s	user 0.127s	sys 0.028s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":48,"dirs.run_cpu_time_us":204,"dirs.run_wall_time_us":826,"drs_written":1,"lbm_read_time_us":34,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40148,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1500}
I20260812 06:16:48.358328 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling LogGCOp(02140135c03a4353ade8832502e77527): free 20743880 bytes of WAL
I20260812 06:16:48.358580 13329 log_reader.cc:385] T 02140135c03a4353ade8832502e77527: removed 2 log segments from log reader
I20260812 06:16:48.358644 13329 log.cc:1079] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/02140135c03a4353ade8832502e77527/wal-000000001 (ops 1-6)
I20260812 06:16:48.358693 13329 log.cc:1079] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/02140135c03a4353ade8832502e77527/wal-000000002 (ops 7-11)
I20260812 06:16:48.363716 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: LogGCOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:16:48.364182 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=2.188937
I20260812 06:16:48.376041 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4128,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:48.376504 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527): perf score=1.000000
I20260812 06:16:48.525900 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.149s	user 0.109s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":518,"lbm_read_time_us":10891,"lbm_reads_lt_1ms":468,"lbm_write_time_us":24022,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":344,"threads_started":5,"update_count":2000}
I20260812 06:16:48.526558 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling UndoDeltaBlockGCOp(02140135c03a4353ade8832502e77527): 20513815 bytes on disk
I20260812 06:16:48.527068 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: UndoDeltaBlockGCOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:16:48.527670 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=10.126437
I20260812 06:16:48.565743 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.038s	user 0.020s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16381,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:48.566197 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=2.188937
I20260812 06:16:48.577131 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3999,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:48.577694 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527): perf score=1.000000
I20260812 06:16:48.745584 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.168s	user 0.106s	sys 0.057s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":311,"lbm_read_time_us":11525,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25887,"lbm_writes_lt_1ms":443,"mutex_wait_us":50,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":30976,"update_count":2000}
I20260812 06:16:48.746163 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=10.126437
I20260812 06:16:48.782424 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.036s	user 0.025s	sys 0.005s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":12322,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:48.782891 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=2.188937
I20260812 06:16:48.793990 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4048,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:48.794660 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527): perf score=1.000000
I20260812 06:16:48.911615 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.117s	user 0.088s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713274,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":226,"lbm_read_time_us":8145,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20449,"lbm_writes_lt_1ms":443,"mutex_wait_us":46,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":2000}
I20260812 06:16:48.912159 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=10.126437
I20260812 06:16:48.978132 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.065s	user 0.030s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":44424,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:48.978703 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=2.188937
I20260812 06:16:48.990067 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4023,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:48.990569 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527): perf score=1.000000
I20260812 06:16:49.111855 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.121s	user 0.089s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":931,"lbm_read_time_us":9226,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22972,"lbm_writes_lt_1ms":443,"mutex_wait_us":277,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1152,"update_count":2000}
I20260812 06:16:49.112380 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=10.126437
I20260812 06:16:49.157496 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.045s	user 0.021s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13615,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:49.158221 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=2.188937
I20260812 06:16:49.169199 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4029,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:49.169683 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527): perf score=1.000000
I20260812 06:16:49.308895 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.139s	user 0.091s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":871,"lbm_read_time_us":10799,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20888,"lbm_writes_lt_1ms":443,"mutex_wait_us":311,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:49.309485 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=10.126437
I20260812 06:16:49.354369 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.045s	user 0.030s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14642,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:49.354907 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=2.188937
I20260812 06:16:49.365615 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3906,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:49.366384 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527): perf score=1.000000
I20260812 06:16:49.487687 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.121s	user 0.072s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":186,"lbm_read_time_us":9817,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22327,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":2000}
I20260812 06:16:49.488263 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=10.126437
I20260812 06:16:49.527029 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.039s	user 0.016s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13993,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:49.527550 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=2.188937
I20260812 06:16:49.542827 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.015s	user 0.005s	sys 0.010s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5675,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:49.543576 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushMRSOp(02140135c03a4353ade8832502e77527): perf score=1.000000
I20260812 06:16:49.571287 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushMRSOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.028s	user 0.021s	sys 0.005s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":76,"dirs.run_cpu_time_us":277,"dirs.run_wall_time_us":1531,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1534,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:49.572014 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling LogGCOp(02140135c03a4353ade8832502e77527): free 120553321 bytes of WAL
I20260812 06:16:49.572273 13329 log_reader.cc:385] T 02140135c03a4353ade8832502e77527: removed 12 log segments from log reader
I20260812 06:16:49.572335 13329 log.cc:1079] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/02140135c03a4353ade8832502e77527/wal-000000003 (ops 12-16)
I20260812 06:16:49.572384 13329 log.cc:1079] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/02140135c03a4353ade8832502e77527/wal-000000004 (ops 17-20)
I20260812 06:16:49.572412 13329 log.cc:1079] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/02140135c03a4353ade8832502e77527/wal-000000005 (ops 21-25)
I20260812 06:16:49.572441 13329 log.cc:1079] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/02140135c03a4353ade8832502e77527/wal-000000006 (ops 26-30)
I20260812 06:16:49.572474 13329 log.cc:1079] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/02140135c03a4353ade8832502e77527/wal-000000007 (ops 31-34)
I20260812 06:16:49.572511 13329 log.cc:1079] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/02140135c03a4353ade8832502e77527/wal-000000008 (ops 35-39)
I20260812 06:16:49.572542 13329 log.cc:1079] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/02140135c03a4353ade8832502e77527/wal-000000009 (ops 40-44)
I20260812 06:16:49.572568 13329 log.cc:1079] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/02140135c03a4353ade8832502e77527/wal-000000010 (ops 45-49)
I20260812 06:16:49.572599 13329 log.cc:1079] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/02140135c03a4353ade8832502e77527/wal-000000011 (ops 50-54)
I20260812 06:16:49.572631 13329 log.cc:1079] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/02140135c03a4353ade8832502e77527/wal-000000012 (ops 55-59)
I20260812 06:16:49.572659 13329 log.cc:1079] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/02140135c03a4353ade8832502e77527/wal-000000013 (ops 60-64)
I20260812 06:16:49.572687 13329 log.cc:1079] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/02140135c03a4353ade8832502e77527/wal-000000014 (ops 65-69)
I20260812 06:16:49.598143 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: LogGCOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.026s	user 0.003s	sys 0.023s Metrics: {}
I20260812 06:16:49.598590 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=3.181125
I20260812 06:16:49.614233 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.015s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":3989,"lbm_writes_lt_1ms":113,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":550}
I20260812 06:16:49.614728 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=2.188937
I20260812 06:16:49.624126 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3339,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:49.624642 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling UndoDeltaBlockGCOp(02140135c03a4353ade8832502e77527): 447 bytes on disk
I20260812 06:16:49.625092 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: UndoDeltaBlockGCOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:16:49.625563 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527): perf score=1.000000
I20260812 06:16:49.795832 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.170s	user 0.135s	sys 0.032s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918324,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":303,"lbm_read_time_us":10712,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31172,"lbm_writes_lt_1ms":643,"mutex_wait_us":35,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":16896,"thread_start_us":75,"threads_started":1,"update_count":3000}
I20260812 06:16:49.796448 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=14.095187
I20260812 06:16:49.847132 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.050s	user 0.022s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22235,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:49.847682 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=2.188937
I20260812 06:16:49.862792 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5574,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:49.863337 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527): perf score=1.000000
I20260812 06:16:50.018098 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.155s	user 0.125s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1632,"lbm_read_time_us":11253,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29131,"lbm_writes_lt_1ms":543,"mutex_wait_us":53,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2500}
I20260812 06:16:50.018667 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=12.110812
I20260812 06:16:50.051568 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.033s	user 0.023s	sys 0.008s Metrics: {"bytes_written":13948451,"delete_count":0,"lbm_write_time_us":14269,"lbm_writes_lt_1ms":343,"reinsert_count":0,"update_count":1700}
I20260812 06:16:50.052112 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=1.196750
I20260812 06:16:50.063170 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.011s	user 0.000s	sys 0.008s Metrics: {"bytes_written":2461654,"delete_count":0,"lbm_write_time_us":3384,"lbm_writes_lt_1ms":63,"reinsert_count":0,"update_count":300}
I20260812 06:16:50.063666 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527): perf score=1.000000
I20260812 06:16:50.210098 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.146s	user 0.102s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713228,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":840,"lbm_read_time_us":10385,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23743,"lbm_writes_lt_1ms":443,"mutex_wait_us":255,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1152,"update_count":2000}
I20260812 06:16:50.210662 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=10.126437
I20260812 06:16:50.241536 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.031s	user 0.011s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12798,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:50.242233 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=2.188937
I20260812 06:16:50.259002 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.017s	user 0.003s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6540,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:50.259789 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527): perf score=1.000000
I20260812 06:16:50.388873 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.129s	user 0.097s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":229,"lbm_read_time_us":10125,"lbm_reads_lt_1ms":464,"lbm_write_time_us":21475,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2000}
I20260812 06:16:50.389451 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=10.126437
I20260812 06:16:50.422737 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.033s	user 0.014s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13048,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:50.423362 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=2.188937
I20260812 06:16:50.433745 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3823,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:50.434337 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527): perf score=1.000000
I20260812 06:16:50.555523 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.121s	user 0.084s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":563,"lbm_read_time_us":8052,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23265,"lbm_writes_lt_1ms":443,"mutex_wait_us":292,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13440,"update_count":2000}
I20260812 06:16:50.556092 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=10.126437
I20260812 06:16:50.603253 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.047s	user 0.019s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18829,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:16:50.603777 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=2.188937
I20260812 06:16:50.613912 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3585,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:50.614601 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527): perf score=1.000000
I20260812 06:16:50.738215 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.123s	user 0.080s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2950,"lbm_read_time_us":9071,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21986,"lbm_writes_lt_1ms":443,"mutex_wait_us":2612,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":98304,"update_count":2000}
I20260812 06:16:50.738901 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=10.126437
I20260812 06:16:50.789877 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.051s	user 0.011s	sys 0.025s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12753,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:50.790498 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=2.188937
I20260812 06:16:50.800830 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3895,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:50.801322 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527): perf score=1.000000
I20260812 06:16:50.938087 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.137s	user 0.117s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":339,"lbm_read_time_us":10178,"lbm_reads_lt_1ms":472,"lbm_write_time_us":19711,"lbm_writes_lt_1ms":443,"mutex_wait_us":64,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2000}
I20260812 06:16:50.938594 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=10.126437
I20260812 06:16:50.972142 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.033s	user 0.014s	sys 0.013s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12033,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:50.972694 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushMRSOp(02140135c03a4353ade8832502e77527): perf score=1.000000
I20260812 06:16:51.011124 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushMRSOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.038s	user 0.025s	sys 0.001s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":241,"dirs.run_wall_time_us":1398,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1589,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:51.011976 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=3.181125
I20260812 06:16:51.024415 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":3851,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:51.024976 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling LogGCOp(02140135c03a4353ade8832502e77527): free 124257306 bytes of WAL
I20260812 06:16:51.025223 13329 log_reader.cc:385] T 02140135c03a4353ade8832502e77527: removed 12 log segments from log reader
I20260812 06:16:51.025285 13329 log.cc:1079] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/02140135c03a4353ade8832502e77527/wal-000000015 (ops 70-74)
I20260812 06:16:51.025331 13329 log.cc:1079] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/02140135c03a4353ade8832502e77527/wal-000000016 (ops 75-79)
I20260812 06:16:51.025363 13329 log.cc:1079] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/02140135c03a4353ade8832502e77527/wal-000000017 (ops 80-84)
I20260812 06:16:51.025393 13329 log.cc:1079] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/02140135c03a4353ade8832502e77527/wal-000000018 (ops 85-89)
I20260812 06:16:51.025422 13329 log.cc:1079] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/02140135c03a4353ade8832502e77527/wal-000000019 (ops 90-94)
I20260812 06:16:51.025455 13329 log.cc:1079] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/02140135c03a4353ade8832502e77527/wal-000000020 (ops 95-99)
I20260812 06:16:51.025480 13329 log.cc:1079] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/02140135c03a4353ade8832502e77527/wal-000000021 (ops 100-104)
I20260812 06:16:51.025506 13329 log.cc:1079] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/02140135c03a4353ade8832502e77527/wal-000000022 (ops 105-109)
I20260812 06:16:51.025534 13329 log.cc:1079] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/02140135c03a4353ade8832502e77527/wal-000000023 (ops 110-114)
I20260812 06:16:51.025563 13329 log.cc:1079] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/02140135c03a4353ade8832502e77527/wal-000000024 (ops 115-118)
I20260812 06:16:51.025592 13329 log.cc:1079] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/02140135c03a4353ade8832502e77527/wal-000000025 (ops 119-123)
I20260812 06:16:51.025624 13329 log.cc:1079] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/02140135c03a4353ade8832502e77527/wal-000000026 (ops 124-128)
I20260812 06:16:51.050413 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: LogGCOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.025s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:16:51.050925 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling UndoDeltaBlockGCOp(02140135c03a4353ade8832502e77527): 481 bytes on disk
I20260812 06:16:51.051447 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: UndoDeltaBlockGCOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:16:51.052033 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=2.188937
I20260812 06:16:51.076941 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.025s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3931,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:51.077589 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=2.188937
I20260812 06:16:51.091995 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5341,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:51.092589 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527): perf score=1.000000
I20260812 06:16:51.281065 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.188s	user 0.107s	sys 0.079s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918325,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2814,"lbm_read_time_us":14079,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30263,"lbm_writes_lt_1ms":643,"mutex_wait_us":2200,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":43520,"thread_start_us":107,"threads_started":1,"update_count":3000}
I20260812 06:16:51.281713 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=14.095187
I20260812 06:16:51.336678 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.055s	user 0.016s	sys 0.036s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20588,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:51.337383 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=2.188937
I20260812 06:16:51.347965 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.010s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3968,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:51.348511 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527): perf score=1.000000
I20260812 06:16:51.517100 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.168s	user 0.109s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":584,"lbm_read_time_us":11709,"lbm_reads_lt_1ms":572,"lbm_write_time_us":24325,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:16:51.517606 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=14.095187
I20260812 06:16:51.575377 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.058s	user 0.035s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23031,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:51.575882 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=2.188937
I20260812 06:16:51.594152 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.018s	user 0.015s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3871,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:51.594682 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527): perf score=1.000000
I20260812 06:16:51.771006 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.176s	user 0.111s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1235,"lbm_read_time_us":13956,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26294,"lbm_writes_lt_1ms":543,"mutex_wait_us":304,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":2500}
I20260812 06:16:51.771534 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=11.118625
I20260812 06:16:51.805024 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.033s	user 0.023s	sys 0.007s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":14204,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:51.805761 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=2.188937
I20260812 06:16:51.817552 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4109,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:51.818080 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527): perf score=1.000000
I20260812 06:16:51.939250 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.121s	user 0.074s	sys 0.046s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713265,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":720,"lbm_read_time_us":7566,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22094,"lbm_writes_lt_1ms":443,"mutex_wait_us":277,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":2000}
I20260812 06:16:51.939832 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=10.126437
I20260812 06:16:51.976959 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.037s	user 0.027s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16116,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:51.977552 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=2.188937
I20260812 06:16:51.990653 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4423,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:51.991215 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527): perf score=1.000000
I20260812 06:16:52.111804 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.120s	user 0.098s	sys 0.022s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1081,"lbm_read_time_us":7265,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22574,"lbm_writes_lt_1ms":443,"mutex_wait_us":275,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2000}
I20260812 06:16:52.112442 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=10.126437
I20260812 06:16:52.155256 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.041s	user 0.018s	sys 0.014s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14148,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:52.155860 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=2.188937
I20260812 06:16:52.166213 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3575,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:52.166942 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527): perf score=1.000000
I20260812 06:16:52.292591 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.125s	user 0.097s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":297,"lbm_read_time_us":7811,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23201,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":71680,"update_count":2000}
I20260812 06:16:52.293141 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=10.126437
I20260812 06:16:52.343170 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.050s	user 0.023s	sys 0.021s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16343,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:52.343737 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=2.188937
I20260812 06:16:52.354127 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.010s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3887,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:52.354585 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushMRSOp(02140135c03a4353ade8832502e77527): perf score=1.000000
I20260812 06:16:52.385262 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushMRSOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.031s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":208,"dirs.run_wall_time_us":1385,"drs_written":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1789,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:52.386055 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527): perf score=1.000000
I20260812 06:16:52.533032 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.147s	user 0.108s	sys 0.034s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1357,"lbm_read_time_us":9480,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23743,"lbm_writes_lt_1ms":443,"mutex_wait_us":298,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:16:52.533674 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling LogGCOp(02140135c03a4353ade8832502e77527): free 120553636 bytes of WAL
I20260812 06:16:52.533900 13329 log_reader.cc:385] T 02140135c03a4353ade8832502e77527: removed 12 log segments from log reader
I20260812 06:16:52.533942 13329 log.cc:1079] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/02140135c03a4353ade8832502e77527/wal-000000027 (ops 129-133)
I20260812 06:16:52.534036 13329 log.cc:1079] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/02140135c03a4353ade8832502e77527/wal-000000028 (ops 134-138)
I20260812 06:16:52.534073 13329 log.cc:1079] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/02140135c03a4353ade8832502e77527/wal-000000029 (ops 139-143)
I20260812 06:16:52.534101 13329 log.cc:1079] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/02140135c03a4353ade8832502e77527/wal-000000030 (ops 144-148)
I20260812 06:16:52.534132 13329 log.cc:1079] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/02140135c03a4353ade8832502e77527/wal-000000031 (ops 149-153)
I20260812 06:16:52.534194 13329 log.cc:1079] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/02140135c03a4353ade8832502e77527/wal-000000032 (ops 154-158)
I20260812 06:16:52.534231 13329 log.cc:1079] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/02140135c03a4353ade8832502e77527/wal-000000033 (ops 159-163)
I20260812 06:16:52.534258 13329 log.cc:1079] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/02140135c03a4353ade8832502e77527/wal-000000034 (ops 164-168)
I20260812 06:16:52.534291 13329 log.cc:1079] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/02140135c03a4353ade8832502e77527/wal-000000035 (ops 169-172)
I20260812 06:16:52.534349 13329 log.cc:1079] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/02140135c03a4353ade8832502e77527/wal-000000036 (ops 173-177)
I20260812 06:16:52.534386 13329 log.cc:1079] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/02140135c03a4353ade8832502e77527/wal-000000037 (ops 178-182)
I20260812 06:16:52.534442 13329 log.cc:1079] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: Deleting log segment in path: /tmp/dist-test-taskZkXGFe/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515402355728-12836-0/minicluster-data/ts-0-root/wals/02140135c03a4353ade8832502e77527/wal-000000038 (ops 183-186)
I20260812 06:16:52.556838 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: LogGCOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.023s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:16:52.557394 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=14.095187
I20260812 06:16:52.601666 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.044s	user 0.032s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19246,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:52.602298 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling UndoDeltaBlockGCOp(02140135c03a4353ade8832502e77527): 447 bytes on disk
I20260812 06:16:52.602892 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: UndoDeltaBlockGCOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":88,"lbm_reads_lt_1ms":4}
I20260812 06:16:52.603545 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=2.188937
I20260812 06:16:52.619179 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5666,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:52.619649 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527): perf score=1.000000
I20260812 06:16:52.733199 12836 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.699s	user 1.697s	sys 0.187s
I20260812 06:16:52.761260 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.141s	user 0.108s	sys 0.031s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"lbm_read_time_us":11001,"lbm_reads_lt_1ms":560,"lbm_write_time_us":28634,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:52.761801 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527): perf score=10.126437
I20260812 06:16:52.787663 12836 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.054s	user 0.002s	sys 0.000s
I20260812 06:16:52.788139 12836 tablet_server.cc:179] TabletServer@127.12.137.1:0 shutting down...
I20260812 06:16:52.791146 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: FlushDeltaMemStoresOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.029s	user 0.014s	sys 0.014s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12031,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:52.791774 13438 maintenance_manager.cc:419] P 47e896ccf2e94a76bb7bbcbbc4f342b6: Scheduling MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527): perf score=1.000000
I20260812 06:16:52.885620 13329 maintenance_manager.cc:643] P 47e896ccf2e94a76bb7bbcbbc4f342b6: MajorDeltaCompactionOp(02140135c03a4353ade8832502e77527) complete. Timing: real 0.094s	user 0.069s	sys 0.024s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16610742,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":590,"lbm_read_time_us":6717,"lbm_reads_lt_1ms":367,"lbm_write_time_us":19630,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":342,"mutex_wait_us":90,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":1500}
I20260812 06:16:52.886340 12836 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:52.886608 12836 tablet_replica.cc:333] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6: stopping tablet replica
I20260812 06:16:52.886737 12836 raft_consensus.cc:2243] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:52.886891 12836 raft_consensus.cc:2272] T 02140135c03a4353ade8832502e77527 P 47e896ccf2e94a76bb7bbcbbc4f342b6 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:52.900796 12836 tablet_server.cc:196] TabletServer@127.12.137.1:0 shutdown complete.
I20260812 06:16:52.916802 12836 master.cc:562] Master@127.12.137.62:43725 shutting down...
I20260812 06:16:52.919999 12836 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 2cef0dde49c74dd096afbf7d7aae5e96 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:52.920203 12836 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 2cef0dde49c74dd096afbf7d7aae5e96 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:52.920372 12836 tablet_replica.cc:333] T 00000000000000000000000000000000 P 2cef0dde49c74dd096afbf7d7aae5e96: stopping tablet replica
I20260812 06:16:52.932798 12836 master.cc:584] Master@127.12.137.62:43725 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5165 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10637 ms total)

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