[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:18:03.386194  3958 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.3.221.190:37447
I20260812 06:18:03.387180  3958 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:18:03.387733  3958 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:18:03.393774  3958 server_base.cc:1061] running on GCE node
W20260812 06:18:03.393953  3964 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:03.393977  3968 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:03.394048  3965 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:03.394569  3958 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:03.394685  3958 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:03.394729  3958 hybrid_clock.cc:648] HybridClock initialized: now 1786515483394726 us; error 0 us; skew 500 ppm
I20260812 06:18:03.396859  3958 webserver.cc:533] Webserver started at http://127.3.221.190:41363/ using document root <none> and password file <none>
I20260812 06:18:03.397607  3958 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:03.397678  3958 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:03.397924  3958 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:03.399873  3958 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/master-0-root/instance:
uuid: "e40798837e4e472998b24d2a335f2b75"
format_stamp: "Formatted at 2026-08-12 06:18:03 on dist-test-slave-bndk"
I20260812 06:18:03.404121  3958 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.003s	sys 0.000s
I20260812 06:18:03.406309  3979 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:03.407225  3958 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:03.407336  3958 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/master-0-root
uuid: "e40798837e4e472998b24d2a335f2b75"
format_stamp: "Formatted at 2026-08-12 06:18:03 on dist-test-slave-bndk"
I20260812 06:18:03.407426  3958 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:03.431772  3958 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:03.432363  3958 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:18:03.432508  3958 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:03.439754  4079 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.221.190:37447 every 8 connection(s)
I20260812 06:18:03.439755  3958 rpc_server.cc:307] RPC server started. Bound to: 127.3.221.190:37447
I20260812 06:18:03.441915  4080 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:03.447118  4080 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e40798837e4e472998b24d2a335f2b75: Bootstrap starting.
I20260812 06:18:03.449347  4080 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P e40798837e4e472998b24d2a335f2b75: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:03.450145  4080 log.cc:826] T 00000000000000000000000000000000 P e40798837e4e472998b24d2a335f2b75: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:03.451669  4080 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e40798837e4e472998b24d2a335f2b75: No bootstrap required, opened a new log
I20260812 06:18:03.454236  4080 raft_consensus.cc:359] T 00000000000000000000000000000000 P e40798837e4e472998b24d2a335f2b75 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e40798837e4e472998b24d2a335f2b75" member_type: VOTER }
I20260812 06:18:03.454384  4080 raft_consensus.cc:385] T 00000000000000000000000000000000 P e40798837e4e472998b24d2a335f2b75 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:03.454437  4080 raft_consensus.cc:740] T 00000000000000000000000000000000 P e40798837e4e472998b24d2a335f2b75 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e40798837e4e472998b24d2a335f2b75, State: Initialized, Role: FOLLOWER
I20260812 06:18:03.454982  4080 consensus_queue.cc:260] T 00000000000000000000000000000000 P e40798837e4e472998b24d2a335f2b75 [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: "e40798837e4e472998b24d2a335f2b75" member_type: VOTER }
I20260812 06:18:03.455120  4080 raft_consensus.cc:399] T 00000000000000000000000000000000 P e40798837e4e472998b24d2a335f2b75 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:03.455165  4080 raft_consensus.cc:493] T 00000000000000000000000000000000 P e40798837e4e472998b24d2a335f2b75 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:03.455250  4080 raft_consensus.cc:3060] T 00000000000000000000000000000000 P e40798837e4e472998b24d2a335f2b75 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:03.455921  4080 raft_consensus.cc:515] T 00000000000000000000000000000000 P e40798837e4e472998b24d2a335f2b75 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e40798837e4e472998b24d2a335f2b75" member_type: VOTER }
I20260812 06:18:03.456272  4080 leader_election.cc:304] T 00000000000000000000000000000000 P e40798837e4e472998b24d2a335f2b75 [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: e40798837e4e472998b24d2a335f2b75; no voters: 
I20260812 06:18:03.456521  4080 leader_election.cc:290] T 00000000000000000000000000000000 P e40798837e4e472998b24d2a335f2b75 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:03.456637  4083 raft_consensus.cc:2804] T 00000000000000000000000000000000 P e40798837e4e472998b24d2a335f2b75 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:03.456843  4083 raft_consensus.cc:697] T 00000000000000000000000000000000 P e40798837e4e472998b24d2a335f2b75 [term 1 LEADER]: Becoming Leader. State: Replica: e40798837e4e472998b24d2a335f2b75, State: Running, Role: LEADER
I20260812 06:18:03.457183  4083 consensus_queue.cc:237] T 00000000000000000000000000000000 P e40798837e4e472998b24d2a335f2b75 [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: "e40798837e4e472998b24d2a335f2b75" member_type: VOTER }
I20260812 06:18:03.457347  4080 sys_catalog.cc:565] T 00000000000000000000000000000000 P e40798837e4e472998b24d2a335f2b75 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:03.458992  4085 sys_catalog.cc:455] T 00000000000000000000000000000000 P e40798837e4e472998b24d2a335f2b75 [sys.catalog]: SysCatalogTable state changed. Reason: New leader e40798837e4e472998b24d2a335f2b75. Latest consensus state: current_term: 1 leader_uuid: "e40798837e4e472998b24d2a335f2b75" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e40798837e4e472998b24d2a335f2b75" member_type: VOTER } }
I20260812 06:18:03.459113  4085 sys_catalog.cc:458] T 00000000000000000000000000000000 P e40798837e4e472998b24d2a335f2b75 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:03.459422  4084 sys_catalog.cc:455] T 00000000000000000000000000000000 P e40798837e4e472998b24d2a335f2b75 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "e40798837e4e472998b24d2a335f2b75" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e40798837e4e472998b24d2a335f2b75" member_type: VOTER } }
I20260812 06:18:03.459504  4084 sys_catalog.cc:458] T 00000000000000000000000000000000 P e40798837e4e472998b24d2a335f2b75 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:03.459496  3958 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:03.459479  4110 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:03.461673  4110 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:03.465754  4110 catalog_manager.cc:1383] Generated new cluster ID: c795446f8cd64849810b634d64693ea2
I20260812 06:18:03.465802  4110 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:03.487244  4110 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:03.487985  4110 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:03.495018  4110 catalog_manager.cc:6092] T 00000000000000000000000000000000 P e40798837e4e472998b24d2a335f2b75: Generated new TSK 0
I20260812 06:18:03.495544  4110 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:03.524351  3958 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:03.527213  4118 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:03.527316  4120 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:03.527370  4126 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:03.527565  3958 server_base.cc:1061] running on GCE node
I20260812 06:18:03.527772  3958 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:03.527812  3958 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:03.527832  3958 hybrid_clock.cc:648] HybridClock initialized: now 1786515483527831 us; error 0 us; skew 500 ppm
I20260812 06:18:03.528676  3958 webserver.cc:533] Webserver started at http://127.3.221.129:44823/ using document root <none> and password file <none>
I20260812 06:18:03.528831  3958 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:03.528880  3958 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:03.528962  3958 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:03.529362  3958 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/instance:
uuid: "8bb4c08a7901472ba4b004b2aea78af8"
format_stamp: "Formatted at 2026-08-12 06:18:03 on dist-test-slave-bndk"
I20260812 06:18:03.530740  3958 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:03.531633  4131 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:03.531876  3958 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:03.531947  3958 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root
uuid: "8bb4c08a7901472ba4b004b2aea78af8"
format_stamp: "Formatted at 2026-08-12 06:18:03 on dist-test-slave-bndk"
I20260812 06:18:03.532015  3958 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:03.545044  3958 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:03.545641  3958 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:03.546079  3958 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:03.546924  3958 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:03.546977  3958 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:03.547088  3958 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:03.547144  3958 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:03.553138  3958 rpc_server.cc:307] RPC server started. Bound to: 127.3.221.129:40307
I20260812 06:18:03.553246  4249 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.221.129:40307 every 8 connection(s)
I20260812 06:18:03.565418  4250 heartbeater.cc:344] Connected to a master server at 127.3.221.190:37447
I20260812 06:18:03.565647  4250 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:03.566131  4250 heartbeater.cc:507] Master 127.3.221.190:37447 requested a full tablet report, sending...
I20260812 06:18:03.567493  4008 ts_manager.cc:194] Registered new tserver with Master: 8bb4c08a7901472ba4b004b2aea78af8 (127.3.221.129:40307)
I20260812 06:18:03.568252  3958 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.014504909s
I20260812 06:18:03.568768  4008 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:60724
I20260812 06:18:03.576963  4008 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:60728:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:03.589615  4182 tablet_service.cc:1511] Processing CreateTablet for tablet 7f747cd6c2d046f08c0179b4ed7b7b25 (DEFAULT_TABLE table=heavy-update-compaction-test [id=c5add7fd47e546819d5b69d6fa95e4c7]), partition=
I20260812 06:18:03.590015  4182 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 7f747cd6c2d046f08c0179b4ed7b7b25. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:03.592566  4266 tablet_bootstrap.cc:492] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Bootstrap starting.
I20260812 06:18:03.594005  4266 tablet_bootstrap.cc:654] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:03.595280  4266 tablet_bootstrap.cc:492] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: No bootstrap required, opened a new log
I20260812 06:18:03.595373  4266 ts_tablet_manager.cc:1403] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Time spent bootstrapping tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:18:03.595770  4266 raft_consensus.cc:359] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8bb4c08a7901472ba4b004b2aea78af8" member_type: VOTER last_known_addr { host: "127.3.221.129" port: 40307 } }
I20260812 06:18:03.595861  4266 raft_consensus.cc:385] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:03.595893  4266 raft_consensus.cc:740] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8bb4c08a7901472ba4b004b2aea78af8, State: Initialized, Role: FOLLOWER
I20260812 06:18:03.596019  4266 consensus_queue.cc:260] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8 [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: "8bb4c08a7901472ba4b004b2aea78af8" member_type: VOTER last_known_addr { host: "127.3.221.129" port: 40307 } }
I20260812 06:18:03.596108  4266 raft_consensus.cc:399] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:03.596148  4266 raft_consensus.cc:493] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:03.596197  4266 raft_consensus.cc:3060] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:03.596855  4266 raft_consensus.cc:515] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8bb4c08a7901472ba4b004b2aea78af8" member_type: VOTER last_known_addr { host: "127.3.221.129" port: 40307 } }
I20260812 06:18:03.596967  4266 leader_election.cc:304] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8 [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: 8bb4c08a7901472ba4b004b2aea78af8; no voters: 
I20260812 06:18:03.597146  4266 leader_election.cc:290] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:03.597277  4268 raft_consensus.cc:2804] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:03.597483  4266 ts_tablet_manager.cc:1434] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:18:03.597493  4268 raft_consensus.cc:697] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8 [term 1 LEADER]: Becoming Leader. State: Replica: 8bb4c08a7901472ba4b004b2aea78af8, State: Running, Role: LEADER
I20260812 06:18:03.597708  4268 consensus_queue.cc:237] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8 [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: "8bb4c08a7901472ba4b004b2aea78af8" member_type: VOTER last_known_addr { host: "127.3.221.129" port: 40307 } }
I20260812 06:18:03.597936  4250 heartbeater.cc:499] Master 127.3.221.190:37447 was elected leader, sending a full tablet report...
I20260812 06:18:03.600277  4008 catalog_manager.cc:5719] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8 reported cstate change: term changed from 0 to 1, leader changed from <none> to 8bb4c08a7901472ba4b004b2aea78af8 (127.3.221.129). New cstate: current_term: 1 leader_uuid: "8bb4c08a7901472ba4b004b2aea78af8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8bb4c08a7901472ba4b004b2aea78af8" member_type: VOTER last_known_addr { host: "127.3.221.129" port: 40307 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:03.659890  3958 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.019s	sys 0.009s
I20260812 06:18:03.804993  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushMRSOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=19.054940
I20260812 06:18:03.958789  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushMRSOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.153s	user 0.122s	sys 0.028s Metrics: {"bytes_written":11897250,"cfile_init":1,"compiler_manager_pool.queue_time_us":207,"delete_count":0,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":211,"dirs.run_wall_time_us":802,"drs_written":1,"lbm_read_time_us":93,"lbm_reads_lt_1ms":4,"lbm_write_time_us":37964,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"thread_start_us":129,"threads_started":1,"update_count":1450}
I20260812 06:18:03.959852  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling LogGCOp(7f747cd6c2d046f08c0179b4ed7b7b25): free 20743880 bytes of WAL
I20260812 06:18:03.960147  4137 log_reader.cc:385] T 7f747cd6c2d046f08c0179b4ed7b7b25: removed 2 log segments from log reader
I20260812 06:18:03.960208  4137 log.cc:1079] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/7f747cd6c2d046f08c0179b4ed7b7b25/wal-000000001 (ops 1-6)
I20260812 06:18:03.960285  4137 log.cc:1079] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/7f747cd6c2d046f08c0179b4ed7b7b25/wal-000000002 (ops 7-11)
I20260812 06:18:03.963984  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: LogGCOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:03.964323  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=2.188937
I20260812 06:18:03.979138  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.015s	user 0.000s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5361,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.979544  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=1.000000
I20260812 06:18:04.104423  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.125s	user 0.094s	sys 0.027s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20303032,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":300,"lbm_read_time_us":6701,"lbm_reads_lt_1ms":458,"lbm_write_time_us":20288,"lbm_writes_lt_1ms":433,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":280,"threads_started":5,"update_count":1950}
I20260812 06:18:04.104902  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling UndoDeltaBlockGCOp(7f747cd6c2d046f08c0179b4ed7b7b25): 16821645 bytes on disk
I20260812 06:18:04.105638  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: UndoDeltaBlockGCOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:18:04.106216  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=10.126437
I20260812 06:18:04.147784  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.041s	user 0.021s	sys 0.011s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15403,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:04.148211  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=2.188937
I20260812 06:18:04.157593  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.009s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3614,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.157934  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=1.000000
I20260812 06:18:04.294595  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.137s	user 0.106s	sys 0.030s 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":89,"lbm_read_time_us":9965,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23975,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:04.295140  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=10.126437
I20260812 06:18:04.329977  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.034s	user 0.022s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13726,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":1500}
I20260812 06:18:04.330391  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=2.188937
I20260812 06:18:04.344937  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5635,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.345440  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=1.000000
I20260812 06:18:04.468559  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.123s	user 0.090s	sys 0.033s 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":147,"lbm_read_time_us":10795,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21326,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2000}
I20260812 06:18:04.469013  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=10.126437
I20260812 06:18:04.515424  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.046s	user 0.017s	sys 0.023s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15194,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:04.515911  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=2.188937
I20260812 06:18:04.525821  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3886,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.526276  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=1.000000
I20260812 06:18:04.658702  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.132s	user 0.084s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":752,"lbm_read_time_us":9262,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20067,"lbm_writes_lt_1ms":443,"mutex_wait_us":259,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2000}
I20260812 06:18:04.659263  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=10.126437
I20260812 06:18:04.696054  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.037s	user 0.022s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15814,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:04.696640  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=1.000000
I20260812 06:18:04.794353  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.098s	user 0.078s	sys 0.020s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16610741,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":245,"lbm_read_time_us":6837,"lbm_reads_lt_1ms":363,"lbm_write_time_us":16254,"lbm_writes_lt_1ms":343,"mutex_wait_us":38,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":1500}
I20260812 06:18:04.794827  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=10.126437
I20260812 06:18:04.835008  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.040s	user 0.027s	sys 0.000s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":12337,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:04.835414  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=2.188937
I20260812 06:18:04.844623  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3509,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.845094  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=1.000000
I20260812 06:18:04.957163  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.112s	user 0.089s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713270,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":603,"lbm_read_time_us":7380,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22675,"lbm_writes_lt_1ms":443,"mutex_wait_us":50,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:04.957651  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=10.126437
I20260812 06:18:04.998072  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.040s	user 0.025s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12599,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:04.998574  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=2.188937
I20260812 06:18:05.008630  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3842,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.009059  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=1.000000
I20260812 06:18:05.138203  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.129s	user 0.089s	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":213,"lbm_read_time_us":9666,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20459,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2000}
I20260812 06:18:05.138665  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=10.126437
I20260812 06:18:05.184681  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.046s	user 0.017s	sys 0.024s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":22674,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:05.185161  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=2.188937
I20260812 06:18:05.194557  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.009s	user 0.003s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3500,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.194911  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushMRSOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=1.000000
I20260812 06:18:05.223186  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushMRSOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.028s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":35,"dirs.run_cpu_time_us":205,"dirs.run_wall_time_us":1115,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1435,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:05.223945  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling LogGCOp(7f747cd6c2d046f08c0179b4ed7b7b25): free 124710294 bytes of WAL
I20260812 06:18:05.224169  4137 log_reader.cc:385] T 7f747cd6c2d046f08c0179b4ed7b7b25: removed 12 log segments from log reader
I20260812 06:18:05.224226  4137 log.cc:1079] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/7f747cd6c2d046f08c0179b4ed7b7b25/wal-000000003 (ops 12-16)
I20260812 06:18:05.224269  4137 log.cc:1079] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/7f747cd6c2d046f08c0179b4ed7b7b25/wal-000000004 (ops 17-21)
I20260812 06:18:05.224304  4137 log.cc:1079] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/7f747cd6c2d046f08c0179b4ed7b7b25/wal-000000005 (ops 22-26)
I20260812 06:18:05.224329  4137 log.cc:1079] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/7f747cd6c2d046f08c0179b4ed7b7b25/wal-000000006 (ops 27-31)
I20260812 06:18:05.224357  4137 log.cc:1079] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/7f747cd6c2d046f08c0179b4ed7b7b25/wal-000000007 (ops 32-36)
I20260812 06:18:05.224381  4137 log.cc:1079] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/7f747cd6c2d046f08c0179b4ed7b7b25/wal-000000008 (ops 37-41)
I20260812 06:18:05.224406  4137 log.cc:1079] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/7f747cd6c2d046f08c0179b4ed7b7b25/wal-000000009 (ops 42-46)
I20260812 06:18:05.224437  4137 log.cc:1079] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/7f747cd6c2d046f08c0179b4ed7b7b25/wal-000000010 (ops 47-51)
I20260812 06:18:05.224467  4137 log.cc:1079] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/7f747cd6c2d046f08c0179b4ed7b7b25/wal-000000011 (ops 52-56)
I20260812 06:18:05.224493  4137 log.cc:1079] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/7f747cd6c2d046f08c0179b4ed7b7b25/wal-000000012 (ops 57-61)
I20260812 06:18:05.224529  4137 log.cc:1079] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/7f747cd6c2d046f08c0179b4ed7b7b25/wal-000000013 (ops 62-66)
I20260812 06:18:05.224556  4137 log.cc:1079] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/7f747cd6c2d046f08c0179b4ed7b7b25/wal-000000014 (ops 67-71)
I20260812 06:18:05.249737  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: LogGCOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:05.250092  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling UndoDeltaBlockGCOp(7f747cd6c2d046f08c0179b4ed7b7b25): 473 bytes on disk
I20260812 06:18:05.250562  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: UndoDeltaBlockGCOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:18:05.250993  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=3.181125
I20260812 06:18:05.261737  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4149,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:05.262110  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=2.188937
I20260812 06:18:05.275954  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.014s	user 0.004s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3271,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:05.276381  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=1.000000
I20260812 06:18:05.471777  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.195s	user 0.126s	sys 0.064s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918327,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":241,"lbm_read_time_us":13566,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33117,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2048,"thread_start_us":70,"threads_started":1,"update_count":3000}
I20260812 06:18:05.472215  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=14.095187
I20260812 06:18:05.528782  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.056s	user 0.030s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19939,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:05.529299  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=2.188937
I20260812 06:18:05.539398  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3819,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.539935  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=1.000000
I20260812 06:18:05.696560  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.156s	user 0.094s	sys 0.061s 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":456,"lbm_read_time_us":11396,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25591,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:05.697180  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=11.118625
I20260812 06:18:05.730422  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.033s	user 0.024s	sys 0.008s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":13544,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:05.731060  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=2.188937
I20260812 06:18:05.744891  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.014s	user 0.003s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4383,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:05.745481  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=1.000000
I20260812 06:18:05.861506  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.116s	user 0.078s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713264,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":262,"lbm_read_time_us":6478,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22511,"lbm_writes_lt_1ms":443,"mutex_wait_us":85,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2000}
I20260812 06:18:05.861969  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=10.126437
I20260812 06:18:05.890585  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.028s	user 0.015s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12184,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:05.891062  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=2.188937
I20260812 06:18:05.902865  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4076,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.903301  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=1.000000
I20260812 06:18:06.017637  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.114s	user 0.081s	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":1467,"lbm_read_time_us":6965,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22593,"lbm_writes_lt_1ms":443,"mutex_wait_us":501,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":2000}
I20260812 06:18:06.018471  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=10.126437
I20260812 06:18:06.050518  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.030s	user 0.019s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12529,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:06.050922  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=2.188937
I20260812 06:18:06.061517  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3559,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.062127  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=1.000000
I20260812 06:18:06.181471  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.119s	user 0.094s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":756,"lbm_read_time_us":8737,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21589,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:06.181900  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=10.126437
I20260812 06:18:06.223474  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.041s	user 0.018s	sys 0.015s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":11762,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":1500}
I20260812 06:18:06.223991  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=2.188937
I20260812 06:18:06.238571  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.014s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5706,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.239017  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=1.000000
I20260812 06:18:06.373356  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.134s	user 0.092s	sys 0.042s 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":849,"lbm_read_time_us":9691,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22415,"lbm_writes_lt_1ms":443,"mutex_wait_us":263,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2000}
I20260812 06:18:06.373878  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=10.126437
I20260812 06:18:06.418017  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.044s	user 0.019s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15620,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:06.418493  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=2.188937
I20260812 06:18:06.428496  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3772,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.428998  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=1.000000
I20260812 06:18:06.547894  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.119s	user 0.106s	sys 0.011s 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":226,"lbm_read_time_us":9235,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21504,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2000}
I20260812 06:18:06.548507  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=10.126437
I20260812 06:18:06.585009  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.036s	user 0.020s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13019,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:06.585520  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=2.188937
I20260812 06:18:06.594882  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3563,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.595327  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushMRSOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=1.000000
I20260812 06:18:06.628840  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushMRSOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.033s	user 0.028s	sys 0.004s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":215,"dirs.run_wall_time_us":1211,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1501,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:06.629596  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling LogGCOp(7f747cd6c2d046f08c0179b4ed7b7b25): free 133024342 bytes of WAL
I20260812 06:18:06.629798  4137 log_reader.cc:385] T 7f747cd6c2d046f08c0179b4ed7b7b25: removed 13 log segments from log reader
I20260812 06:18:06.629843  4137 log.cc:1079] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/7f747cd6c2d046f08c0179b4ed7b7b25/wal-000000015 (ops 72-76)
I20260812 06:18:06.629870  4137 log.cc:1079] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/7f747cd6c2d046f08c0179b4ed7b7b25/wal-000000016 (ops 77-81)
I20260812 06:18:06.629901  4137 log.cc:1079] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/7f747cd6c2d046f08c0179b4ed7b7b25/wal-000000017 (ops 82-86)
I20260812 06:18:06.629933  4137 log.cc:1079] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/7f747cd6c2d046f08c0179b4ed7b7b25/wal-000000018 (ops 87-91)
I20260812 06:18:06.629966  4137 log.cc:1079] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/7f747cd6c2d046f08c0179b4ed7b7b25/wal-000000019 (ops 92-96)
I20260812 06:18:06.629999  4137 log.cc:1079] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/7f747cd6c2d046f08c0179b4ed7b7b25/wal-000000020 (ops 97-101)
I20260812 06:18:06.630029  4137 log.cc:1079] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/7f747cd6c2d046f08c0179b4ed7b7b25/wal-000000021 (ops 102-106)
I20260812 06:18:06.630061  4137 log.cc:1079] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/7f747cd6c2d046f08c0179b4ed7b7b25/wal-000000022 (ops 107-110)
I20260812 06:18:06.630092  4137 log.cc:1079] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/7f747cd6c2d046f08c0179b4ed7b7b25/wal-000000023 (ops 111-115)
I20260812 06:18:06.630124  4137 log.cc:1079] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/7f747cd6c2d046f08c0179b4ed7b7b25/wal-000000024 (ops 116-120)
I20260812 06:18:06.630156  4137 log.cc:1079] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/7f747cd6c2d046f08c0179b4ed7b7b25/wal-000000025 (ops 121-125)
I20260812 06:18:06.630187  4137 log.cc:1079] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/7f747cd6c2d046f08c0179b4ed7b7b25/wal-000000026 (ops 126-130)
I20260812 06:18:06.630219  4137 log.cc:1079] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/7f747cd6c2d046f08c0179b4ed7b7b25/wal-000000027 (ops 131-135)
I20260812 06:18:06.656713  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: LogGCOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.027s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:18:06.657104  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling UndoDeltaBlockGCOp(7f747cd6c2d046f08c0179b4ed7b7b25): 481 bytes on disk
I20260812 06:18:06.657719  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: UndoDeltaBlockGCOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":86,"lbm_reads_lt_1ms":4}
I20260812 06:18:06.658258  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=6.157687
I20260812 06:18:06.679375  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.021s	user 0.010s	sys 0.009s Metrics: {"bytes_written":7630740,"delete_count":0,"lbm_write_time_us":8171,"lbm_writes_lt_1ms":189,"reinsert_count":0,"update_count":930}
I20260812 06:18:06.679860  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=1.000000
I20260812 06:18:06.842186  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.162s	user 0.126s	sys 0.036s Metrics: {"cfile_cache_miss":619,"cfile_cache_miss_bytes":28343878,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":681,"lbm_read_time_us":10817,"lbm_reads_lt_1ms":651,"lbm_write_time_us":32900,"lbm_writes_lt_1ms":629,"mutex_wait_us":35,"peak_mem_usage":72887214,"reinsert_count":0,"spinlock_wait_cycles":16384,"thread_start_us":70,"threads_started":1,"update_count":2930}
I20260812 06:18:06.842658  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=15.087375
I20260812 06:18:06.923115  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.080s	user 0.033s	sys 0.011s Metrics: {"bytes_written":16984246,"delete_count":0,"lbm_write_time_us":43412,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":416,"reinsert_count":0,"update_count":2070}
I20260812 06:18:06.923563  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=6.157687
I20260812 06:18:06.951589  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.028s	user 0.020s	sys 0.004s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":10975,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:06.952128  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=1.000000
I20260812 06:18:07.113732  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.161s	user 0.113s	sys 0.048s Metrics: {"cfile_cache_miss":646,"cfile_cache_miss_bytes":29492441,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":107,"lbm_read_time_us":12840,"lbm_reads_lt_1ms":678,"lbm_write_time_us":33002,"lbm_writes_lt_1ms":657,"peak_mem_usage":77157346,"reinsert_count":0,"update_count":3070}
I20260812 06:18:07.114243  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=14.095187
I20260812 06:18:07.152281  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.038s	user 0.030s	sys 0.004s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16322,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:18:07.152758  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=2.188937
I20260812 06:18:07.163748  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3805,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:07.164289  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=1.000000
I20260812 06:18:07.310308  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.146s	user 0.115s	sys 0.017s 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":283,"lbm_read_time_us":8792,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26700,"lbm_writes_lt_1ms":543,"mutex_wait_us":58,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2500}
I20260812 06:18:07.310758  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=14.095187
I20260812 06:18:07.372366  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.061s	user 0.033s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22871,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:07.372875  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=2.188937
I20260812 06:18:07.382477  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3427,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:07.383086  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=1.000000
I20260812 06:18:07.539136  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.156s	user 0.101s	sys 0.052s 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":838,"lbm_read_time_us":10788,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27166,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:07.539671  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=14.095187
I20260812 06:18:07.575405  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.036s	user 0.009s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":15803,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:07.576040  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=1.000000
I20260812 06:18:07.716511  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.140s	user 0.093s	sys 0.044s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":758,"lbm_read_time_us":9232,"lbm_reads_lt_1ms":467,"lbm_write_time_us":21787,"lbm_writes_lt_1ms":443,"mutex_wait_us":220,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:07.716989  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=11.118625
I20260812 06:18:07.745325  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.028s	user 0.021s	sys 0.007s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":11750,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:07.745893  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=2.188937
I20260812 06:18:07.770169  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.024s	user 0.006s	sys 0.006s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4721,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:07.770655  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=2.188937
I20260812 06:18:07.780421  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.010s	user 0.007s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3625,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:07.781005  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=1.000000
I20260812 06:18:07.957981  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.177s	user 0.108s	sys 0.053s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":428,"lbm_read_time_us":10557,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31448,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":37,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2500}
I20260812 06:18:07.958484  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=14.095187
I20260812 06:18:07.997555  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.039s	user 0.029s	sys 0.008s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":16425,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:07.998065  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=2.188937
I20260812 06:18:08.007639  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3693,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:08.008118  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushMRSOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=1.000000
I20260812 06:18:08.038141  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushMRSOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.030s	user 0.024s	sys 0.005s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":50,"dirs.run_cpu_time_us":161,"dirs.run_wall_time_us":1163,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2084,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:08.038797  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling LogGCOp(7f747cd6c2d046f08c0179b4ed7b7b25): free 133024654 bytes of WAL
I20260812 06:18:08.039033  4137 log_reader.cc:385] T 7f747cd6c2d046f08c0179b4ed7b7b25: removed 13 log segments from log reader
I20260812 06:18:08.039093  4137 log.cc:1079] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/7f747cd6c2d046f08c0179b4ed7b7b25/wal-000000028 (ops 136-140)
I20260812 06:18:08.039135  4137 log.cc:1079] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/7f747cd6c2d046f08c0179b4ed7b7b25/wal-000000029 (ops 141-145)
I20260812 06:18:08.039166  4137 log.cc:1079] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/7f747cd6c2d046f08c0179b4ed7b7b25/wal-000000030 (ops 146-150)
I20260812 06:18:08.039198  4137 log.cc:1079] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/7f747cd6c2d046f08c0179b4ed7b7b25/wal-000000031 (ops 151-155)
I20260812 06:18:08.039232  4137 log.cc:1079] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/7f747cd6c2d046f08c0179b4ed7b7b25/wal-000000032 (ops 156-160)
I20260812 06:18:08.039264  4137 log.cc:1079] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/7f747cd6c2d046f08c0179b4ed7b7b25/wal-000000033 (ops 161-165)
I20260812 06:18:08.039292  4137 log.cc:1079] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/7f747cd6c2d046f08c0179b4ed7b7b25/wal-000000034 (ops 166-170)
I20260812 06:18:08.039321  4137 log.cc:1079] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/7f747cd6c2d046f08c0179b4ed7b7b25/wal-000000035 (ops 171-174)
I20260812 06:18:08.039350  4137 log.cc:1079] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/7f747cd6c2d046f08c0179b4ed7b7b25/wal-000000036 (ops 175-179)
I20260812 06:18:08.039376  4137 log.cc:1079] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/7f747cd6c2d046f08c0179b4ed7b7b25/wal-000000037 (ops 180-184)
I20260812 06:18:08.039408  4137 log.cc:1079] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/7f747cd6c2d046f08c0179b4ed7b7b25/wal-000000038 (ops 185-189)
I20260812 06:18:08.039441  4137 log.cc:1079] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/7f747cd6c2d046f08c0179b4ed7b7b25/wal-000000039 (ops 190-194)
I20260812 06:18:08.039472  4137 log.cc:1079] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/7f747cd6c2d046f08c0179b4ed7b7b25/wal-000000040 (ops 195-199)
I20260812 06:18:08.068641  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: LogGCOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.030s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:08.068998  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=3.181125
I20260812 06:18:08.086114  3958 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.426s	user 1.618s	sys 0.144s
I20260812 06:18:08.087476  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.018s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4201,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:08.087924  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling UndoDeltaBlockGCOp(7f747cd6c2d046f08c0179b4ed7b7b25): 492 bytes on disk
I20260812 06:18:08.088338  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: UndoDeltaBlockGCOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:18:08.088828  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=2.188937
I20260812 06:18:08.102229  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: FlushDeltaMemStoresOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.013s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5211,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:08.102623  4251 maintenance_manager.cc:419] P 8bb4c08a7901472ba4b004b2aea78af8: Scheduling MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25): perf score=1.000000
I20260812 06:18:08.185348  3958 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.099s	user 0.003s	sys 0.000s
I20260812 06:18:08.185921  3958 tablet_server.cc:179] TabletServer@127.3.221.129:0 shutting down...
I20260812 06:18:08.271261  4137 maintenance_manager.cc:643] P 8bb4c08a7901472ba4b004b2aea78af8: MajorDeltaCompactionOp(7f747cd6c2d046f08c0179b4ed7b7b25) complete. Timing: real 0.168s	user 0.096s	sys 0.072s Metrics: {"cfile_cache_hit":222,"cfile_cache_hit_bytes":8989771,"cfile_cache_miss":512,"cfile_cache_miss_bytes":24030963,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":692,"lbm_read_time_us":12814,"lbm_reads_lt_1ms":544,"lbm_write_time_us":29213,"lbm_writes_lt_1ms":743,"mutex_wait_us":61,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":11136,"thread_start_us":72,"threads_started":1,"update_count":3500}
I20260812 06:18:08.271962  3958 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:08.272436  3958 tablet_replica.cc:333] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8: stopping tablet replica
I20260812 06:18:08.272675  3958 raft_consensus.cc:2243] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:08.272894  3958 raft_consensus.cc:2272] T 7f747cd6c2d046f08c0179b4ed7b7b25 P 8bb4c08a7901472ba4b004b2aea78af8 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:08.287061  3958 tablet_server.cc:196] TabletServer@127.3.221.129:0 shutdown complete.
I20260812 06:18:08.327957  3958 master.cc:562] Master@127.3.221.190:37447 shutting down...
I20260812 06:18:08.331179  3958 raft_consensus.cc:2243] T 00000000000000000000000000000000 P e40798837e4e472998b24d2a335f2b75 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:08.331359  3958 raft_consensus.cc:2272] T 00000000000000000000000000000000 P e40798837e4e472998b24d2a335f2b75 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:08.331439  3958 tablet_replica.cc:333] T 00000000000000000000000000000000 P e40798837e4e472998b24d2a335f2b75: stopping tablet replica
I20260812 06:18:08.343365  3958 master.cc:584] Master@127.3.221.190:37447 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5025 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:08.422869  3958 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.3.221.190:44063
I20260812 06:18:08.423287  3958 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:08.425048  4305 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:08.425136  4299 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:08.425194  4302 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:08.425343  3958 server_base.cc:1061] running on GCE node
I20260812 06:18:08.425482  3958 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:08.425518  3958 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:08.425542  3958 hybrid_clock.cc:648] HybridClock initialized: now 1786515488425542 us; error 0 us; skew 500 ppm
I20260812 06:18:08.426285  3958 webserver.cc:533] Webserver started at http://127.3.221.190:37589/ using document root <none> and password file <none>
I20260812 06:18:08.426429  3958 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:08.426479  3958 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:08.426553  3958 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:08.426903  3958 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/master-0-root/instance:
uuid: "f0ae0fe9be4f40f8b1a8a12c2f347d36"
format_stamp: "Formatted at 2026-08-12 06:18:08 on dist-test-slave-bndk"
I20260812 06:18:08.428292  3958 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:08.429098  4311 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:08.429847  3958 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:08.429919  3958 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/master-0-root
uuid: "f0ae0fe9be4f40f8b1a8a12c2f347d36"
format_stamp: "Formatted at 2026-08-12 06:18:08 on dist-test-slave-bndk"
I20260812 06:18:08.429992  3958 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:08.434267  3958 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:08.434542  3958 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:08.438264  3958 rpc_server.cc:307] RPC server started. Bound to: 127.3.221.190:44063
I20260812 06:18:08.443849  4395 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.221.190:44063 every 8 connection(s)
I20260812 06:18:08.444259  4396 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:08.445989  4396 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f0ae0fe9be4f40f8b1a8a12c2f347d36: Bootstrap starting.
I20260812 06:18:08.446714  4396 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P f0ae0fe9be4f40f8b1a8a12c2f347d36: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:08.447571  4396 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f0ae0fe9be4f40f8b1a8a12c2f347d36: No bootstrap required, opened a new log
I20260812 06:18:08.447914  4396 raft_consensus.cc:359] T 00000000000000000000000000000000 P f0ae0fe9be4f40f8b1a8a12c2f347d36 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f0ae0fe9be4f40f8b1a8a12c2f347d36" member_type: VOTER }
I20260812 06:18:08.448009  4396 raft_consensus.cc:385] T 00000000000000000000000000000000 P f0ae0fe9be4f40f8b1a8a12c2f347d36 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:08.448041  4396 raft_consensus.cc:740] T 00000000000000000000000000000000 P f0ae0fe9be4f40f8b1a8a12c2f347d36 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f0ae0fe9be4f40f8b1a8a12c2f347d36, State: Initialized, Role: FOLLOWER
I20260812 06:18:08.448167  4396 consensus_queue.cc:260] T 00000000000000000000000000000000 P f0ae0fe9be4f40f8b1a8a12c2f347d36 [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: "f0ae0fe9be4f40f8b1a8a12c2f347d36" member_type: VOTER }
I20260812 06:18:08.448235  4396 raft_consensus.cc:399] T 00000000000000000000000000000000 P f0ae0fe9be4f40f8b1a8a12c2f347d36 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:08.448273  4396 raft_consensus.cc:493] T 00000000000000000000000000000000 P f0ae0fe9be4f40f8b1a8a12c2f347d36 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:08.448320  4396 raft_consensus.cc:3060] T 00000000000000000000000000000000 P f0ae0fe9be4f40f8b1a8a12c2f347d36 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:08.448928  4396 raft_consensus.cc:515] T 00000000000000000000000000000000 P f0ae0fe9be4f40f8b1a8a12c2f347d36 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f0ae0fe9be4f40f8b1a8a12c2f347d36" member_type: VOTER }
I20260812 06:18:08.449066  4396 leader_election.cc:304] T 00000000000000000000000000000000 P f0ae0fe9be4f40f8b1a8a12c2f347d36 [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: f0ae0fe9be4f40f8b1a8a12c2f347d36; no voters: 
I20260812 06:18:08.449258  4396 leader_election.cc:290] T 00000000000000000000000000000000 P f0ae0fe9be4f40f8b1a8a12c2f347d36 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:08.449339  4401 raft_consensus.cc:2804] T 00000000000000000000000000000000 P f0ae0fe9be4f40f8b1a8a12c2f347d36 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:08.449520  4401 raft_consensus.cc:697] T 00000000000000000000000000000000 P f0ae0fe9be4f40f8b1a8a12c2f347d36 [term 1 LEADER]: Becoming Leader. State: Replica: f0ae0fe9be4f40f8b1a8a12c2f347d36, State: Running, Role: LEADER
I20260812 06:18:08.449671  4396 sys_catalog.cc:565] T 00000000000000000000000000000000 P f0ae0fe9be4f40f8b1a8a12c2f347d36 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:08.449646  4401 consensus_queue.cc:237] T 00000000000000000000000000000000 P f0ae0fe9be4f40f8b1a8a12c2f347d36 [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: "f0ae0fe9be4f40f8b1a8a12c2f347d36" member_type: VOTER }
I20260812 06:18:08.450039  4406 sys_catalog.cc:455] T 00000000000000000000000000000000 P f0ae0fe9be4f40f8b1a8a12c2f347d36 [sys.catalog]: SysCatalogTable state changed. Reason: New leader f0ae0fe9be4f40f8b1a8a12c2f347d36. Latest consensus state: current_term: 1 leader_uuid: "f0ae0fe9be4f40f8b1a8a12c2f347d36" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f0ae0fe9be4f40f8b1a8a12c2f347d36" member_type: VOTER } }
I20260812 06:18:08.450145  4406 sys_catalog.cc:458] T 00000000000000000000000000000000 P f0ae0fe9be4f40f8b1a8a12c2f347d36 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:08.450019  4404 sys_catalog.cc:455] T 00000000000000000000000000000000 P f0ae0fe9be4f40f8b1a8a12c2f347d36 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "f0ae0fe9be4f40f8b1a8a12c2f347d36" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f0ae0fe9be4f40f8b1a8a12c2f347d36" member_type: VOTER } }
I20260812 06:18:08.450364  4404 sys_catalog.cc:458] T 00000000000000000000000000000000 P f0ae0fe9be4f40f8b1a8a12c2f347d36 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:08.450452  4412 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:08.451114  4412 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:08.451435  3958 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:08.452765  4412 catalog_manager.cc:1383] Generated new cluster ID: c8aed76a094d40b0bdc205cad53ad97f
I20260812 06:18:08.452821  4412 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:08.467936  4412 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:08.468432  4412 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:08.478940  4412 catalog_manager.cc:6092] T 00000000000000000000000000000000 P f0ae0fe9be4f40f8b1a8a12c2f347d36: Generated new TSK 0
I20260812 06:18:08.479096  4412 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:08.483404  3958 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:08.485111  4435 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:08.485086  4436 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:08.485210  4441 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:08.485386  3958 server_base.cc:1061] running on GCE node
I20260812 06:18:08.485522  3958 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:08.485561  3958 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:08.485576  3958 hybrid_clock.cc:648] HybridClock initialized: now 1786515488485576 us; error 0 us; skew 500 ppm
I20260812 06:18:08.486312  3958 webserver.cc:533] Webserver started at http://127.3.221.129:40657/ using document root <none> and password file <none>
I20260812 06:18:08.486454  3958 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:08.486505  3958 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:08.486574  3958 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:08.486903  3958 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root/instance:
uuid: "2281a9051e074d9cbb2656cad0b09c5e"
format_stamp: "Formatted at 2026-08-12 06:18:08 on dist-test-slave-bndk"
I20260812 06:18:08.488181  3958 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:08.488955  4451 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:08.489141  3958 fs_manager.cc:730] Time spent opening block manager: real 0.000s	user 0.001s	sys 0.000s
I20260812 06:18:08.489205  3958 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root
uuid: "2281a9051e074d9cbb2656cad0b09c5e"
format_stamp: "Formatted at 2026-08-12 06:18:08 on dist-test-slave-bndk"
I20260812 06:18:08.489285  3958 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:08.507419  3958 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:08.507757  3958 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:08.508026  3958 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:08.508448  3958 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:08.508486  3958 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:08.508527  3958 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:08.508556  3958 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:08.512477  3958 rpc_server.cc:307] RPC server started. Bound to: 127.3.221.129:34553
I20260812 06:18:08.512530  4574 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.221.129:34553 every 8 connection(s)
I20260812 06:18:08.516832  4575 heartbeater.cc:344] Connected to a master server at 127.3.221.190:44063
I20260812 06:18:08.516917  4575 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:08.517110  4575 heartbeater.cc:507] Master 127.3.221.190:44063 requested a full tablet report, sending...
I20260812 06:18:08.517720  4339 ts_manager.cc:194] Registered new tserver with Master: 2281a9051e074d9cbb2656cad0b09c5e (127.3.221.129:34553)
I20260812 06:18:08.518348  3958 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.005492918s
I20260812 06:18:08.518410  4339 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:41316
I20260812 06:18:08.524415  4339 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:41324:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:08.532112  4500 tablet_service.cc:1511] Processing CreateTablet for tablet 840db6eb970e4f47a411c6e14f950672 (DEFAULT_TABLE table=heavy-update-compaction-test [id=7192bc0cd04e49419c43f9ec6b4e03d7]), partition=
I20260812 06:18:08.532316  4500 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 840db6eb970e4f47a411c6e14f950672. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:08.534103  4596 tablet_bootstrap.cc:492] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Bootstrap starting.
I20260812 06:18:08.534929  4596 tablet_bootstrap.cc:654] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:08.535861  4596 tablet_bootstrap.cc:492] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: No bootstrap required, opened a new log
I20260812 06:18:08.535938  4596 ts_tablet_manager.cc:1403] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:08.536312  4596 raft_consensus.cc:359] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2281a9051e074d9cbb2656cad0b09c5e" member_type: VOTER last_known_addr { host: "127.3.221.129" port: 34553 } }
I20260812 06:18:08.536393  4596 raft_consensus.cc:385] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:08.536422  4596 raft_consensus.cc:740] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 2281a9051e074d9cbb2656cad0b09c5e, State: Initialized, Role: FOLLOWER
I20260812 06:18:08.536545  4596 consensus_queue.cc:260] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e [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: "2281a9051e074d9cbb2656cad0b09c5e" member_type: VOTER last_known_addr { host: "127.3.221.129" port: 34553 } }
I20260812 06:18:08.536617  4596 raft_consensus.cc:399] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:08.536664  4596 raft_consensus.cc:493] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:08.536713  4596 raft_consensus.cc:3060] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:08.537519  4596 raft_consensus.cc:515] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2281a9051e074d9cbb2656cad0b09c5e" member_type: VOTER last_known_addr { host: "127.3.221.129" port: 34553 } }
I20260812 06:18:08.537658  4596 leader_election.cc:304] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e [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: 2281a9051e074d9cbb2656cad0b09c5e; no voters: 
I20260812 06:18:08.537846  4596 leader_election.cc:290] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:08.537943  4599 raft_consensus.cc:2804] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:08.538136  4599 raft_consensus.cc:697] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e [term 1 LEADER]: Becoming Leader. State: Replica: 2281a9051e074d9cbb2656cad0b09c5e, State: Running, Role: LEADER
I20260812 06:18:08.538147  4596 ts_tablet_manager.cc:1434] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:18:08.538157  4575 heartbeater.cc:499] Master 127.3.221.190:44063 was elected leader, sending a full tablet report...
I20260812 06:18:08.538306  4599 consensus_queue.cc:237] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e [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: "2281a9051e074d9cbb2656cad0b09c5e" member_type: VOTER last_known_addr { host: "127.3.221.129" port: 34553 } }
I20260812 06:18:08.539443  4339 catalog_manager.cc:5719] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e reported cstate change: term changed from 0 to 1, leader changed from <none> to 2281a9051e074d9cbb2656cad0b09c5e (127.3.221.129). New cstate: current_term: 1 leader_uuid: "2281a9051e074d9cbb2656cad0b09c5e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2281a9051e074d9cbb2656cad0b09c5e" member_type: VOTER last_known_addr { host: "127.3.221.129" port: 34553 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:08.592089  3958 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.049s	user 0.009s	sys 0.012s
I20260812 06:18:08.763278  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushMRSOp(840db6eb970e4f47a411c6e14f950672): perf score=23.023690
I20260812 06:18:08.912882  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushMRSOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.149s	user 0.100s	sys 0.046s Metrics: {"bytes_written":14030501,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":49,"dirs.run_cpu_time_us":146,"dirs.run_wall_time_us":870,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43177,"lbm_writes_lt_1ms":909,"mutex_wait_us":171,"peak_mem_usage":0,"reinsert_count":0,"rows_written":106,"spinlock_wait_cycles":16256,"update_count":1710}
I20260812 06:18:08.913484  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672): perf score=1.196750
I20260812 06:18:08.926990  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.013s	user 0.002s	sys 0.005s Metrics: {"bytes_written":2830888,"delete_count":0,"lbm_write_time_us":2351,"lbm_writes_lt_1ms":72,"reinsert_count":0,"update_count":345}
I20260812 06:18:08.927345  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling LogGCOp(840db6eb970e4f47a411c6e14f950672): free 20743880 bytes of WAL
I20260812 06:18:08.927521  4458 log_reader.cc:385] T 840db6eb970e4f47a411c6e14f950672: removed 2 log segments from log reader
I20260812 06:18:08.927562  4458 log.cc:1079] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/840db6eb970e4f47a411c6e14f950672/wal-000000001 (ops 1-6)
I20260812 06:18:08.927601  4458 log.cc:1079] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/840db6eb970e4f47a411c6e14f950672/wal-000000002 (ops 7-11)
I20260812 06:18:08.931391  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: LogGCOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:08.931658  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672): perf score=2.188937
I20260812 06:18:08.940095  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.008s	user 0.003s	sys 0.004s Metrics: {"bytes_written":3241130,"delete_count":0,"lbm_write_time_us":3044,"lbm_writes_lt_1ms":82,"reinsert_count":0,"update_count":395}
I20260812 06:18:08.940577  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling MajorDeltaCompactionOp(840db6eb970e4f47a411c6e14f950672): perf score=1.000000
I20260812 06:18:09.102799  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: MajorDeltaCompactionOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.162s	user 0.103s	sys 0.055s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24446484,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":485,"lbm_read_time_us":10778,"lbm_reads_lt_1ms":563,"lbm_write_time_us":25417,"lbm_writes_lt_1ms":533,"mutex_wait_us":65,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":4480,"thread_start_us":307,"threads_started":5,"update_count":2450}
I20260812 06:18:09.103303  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling UndoDeltaBlockGCOp(840db6eb970e4f47a411c6e14f950672): 20924069 bytes on disk
I20260812 06:18:09.103751  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: UndoDeltaBlockGCOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:18:09.104187  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672): perf score=14.095187
I20260812 06:18:09.147289  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.043s	user 0.034s	sys 0.004s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17654,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:09.147810  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling MajorDeltaCompactionOp(840db6eb970e4f47a411c6e14f950672): perf score=1.000000
I20260812 06:18:09.283386  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: MajorDeltaCompactionOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.135s	user 0.095s	sys 0.040s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20754123,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":187,"lbm_read_time_us":10898,"lbm_reads_lt_1ms":463,"lbm_write_time_us":20105,"lbm_writes_lt_1ms":443,"mutex_wait_us":36,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2000}
I20260812 06:18:09.283874  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672): perf score=14.095187
I20260812 06:18:09.330076  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.046s	user 0.032s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19538,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:09.330551  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672): perf score=2.188937
I20260812 06:18:09.341236  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4139,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:09.341820  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling MajorDeltaCompactionOp(840db6eb970e4f47a411c6e14f950672): perf score=1.000000
I20260812 06:18:09.526616  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: MajorDeltaCompactionOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.185s	user 0.141s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856652,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":242,"lbm_read_time_us":12798,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27257,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2500}
I20260812 06:18:09.527097  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672): perf score=14.095187
I20260812 06:18:09.570897  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.044s	user 0.021s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16361,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:09.571429  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672): perf score=2.188937
I20260812 06:18:09.586696  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5830,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:09.587249  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling MajorDeltaCompactionOp(840db6eb970e4f47a411c6e14f950672): perf score=1.000000
I20260812 06:18:09.745415  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: MajorDeltaCompactionOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.158s	user 0.105s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856653,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2482,"lbm_read_time_us":9645,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29323,"lbm_writes_lt_1ms":543,"mutex_wait_us":2118,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2500}
I20260812 06:18:09.745950  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672): perf score=14.095187
I20260812 06:18:09.786168  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.040s	user 0.035s	sys 0.004s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":17428,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:09.786737  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672): perf score=2.188937
I20260812 06:18:09.802485  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6039,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:09.802999  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling MajorDeltaCompactionOp(840db6eb970e4f47a411c6e14f950672): perf score=1.000000
I20260812 06:18:09.950851  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: MajorDeltaCompactionOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.148s	user 0.105s	sys 0.031s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856655,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":485,"lbm_read_time_us":10822,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27325,"lbm_writes_lt_1ms":543,"mutex_wait_us":36,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":2500}
I20260812 06:18:09.951457  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672): perf score=14.095187
I20260812 06:18:09.990480  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.039s	user 0.021s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":16259,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:09.990955  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672): perf score=2.188937
I20260812 06:18:10.005795  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5794,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.006304  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushMRSOp(840db6eb970e4f47a411c6e14f950672): perf score=1.000000
I20260812 06:18:10.029767  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushMRSOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.023s	user 0.023s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":251,"dirs.run_wall_time_us":1317,"drs_written":1,"lbm_read_time_us":34,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1266,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:10.030310  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling LogGCOp(840db6eb970e4f47a411c6e14f950672): free 120553339 bytes of WAL
I20260812 06:18:10.030514  4458 log_reader.cc:385] T 840db6eb970e4f47a411c6e14f950672: removed 12 log segments from log reader
I20260812 06:18:10.030567  4458 log.cc:1079] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/840db6eb970e4f47a411c6e14f950672/wal-000000003 (ops 12-16)
I20260812 06:18:10.030607  4458 log.cc:1079] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/840db6eb970e4f47a411c6e14f950672/wal-000000004 (ops 17-21)
I20260812 06:18:10.030642  4458 log.cc:1079] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/840db6eb970e4f47a411c6e14f950672/wal-000000005 (ops 22-26)
I20260812 06:18:10.030663  4458 log.cc:1079] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/840db6eb970e4f47a411c6e14f950672/wal-000000006 (ops 27-30)
I20260812 06:18:10.030694  4458 log.cc:1079] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/840db6eb970e4f47a411c6e14f950672/wal-000000007 (ops 31-35)
I20260812 06:18:10.030726  4458 log.cc:1079] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/840db6eb970e4f47a411c6e14f950672/wal-000000008 (ops 36-40)
I20260812 06:18:10.030757  4458 log.cc:1079] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/840db6eb970e4f47a411c6e14f950672/wal-000000009 (ops 41-45)
I20260812 06:18:10.030789  4458 log.cc:1079] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/840db6eb970e4f47a411c6e14f950672/wal-000000010 (ops 46-50)
I20260812 06:18:10.030819  4458 log.cc:1079] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/840db6eb970e4f47a411c6e14f950672/wal-000000011 (ops 51-55)
I20260812 06:18:10.030850  4458 log.cc:1079] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/840db6eb970e4f47a411c6e14f950672/wal-000000012 (ops 56-60)
I20260812 06:18:10.030880  4458 log.cc:1079] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/840db6eb970e4f47a411c6e14f950672/wal-000000013 (ops 61-64)
I20260812 06:18:10.030911  4458 log.cc:1079] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/840db6eb970e4f47a411c6e14f950672/wal-000000014 (ops 65-69)
I20260812 06:18:10.050370  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: LogGCOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.020s	user 0.000s	sys 0.019s Metrics: {}
I20260812 06:18:10.050777  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672): perf score=2.188937
I20260812 06:18:10.067541  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.017s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3834,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.068022  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling UndoDeltaBlockGCOp(840db6eb970e4f47a411c6e14f950672): 446 bytes on disk
I20260812 06:18:10.068461  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: UndoDeltaBlockGCOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:18:10.068938  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672): perf score=2.188937
I20260812 06:18:10.078365  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3532,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.078805  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling MajorDeltaCompactionOp(840db6eb970e4f47a411c6e14f950672): perf score=1.000000
I20260812 06:18:10.313613  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: MajorDeltaCompactionOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.235s	user 0.126s	sys 0.093s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33061715,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":219,"lbm_read_time_us":12730,"lbm_reads_lt_1ms":774,"lbm_write_time_us":37170,"lbm_writes_lt_1ms":743,"mutex_wait_us":41,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":7552,"thread_start_us":72,"threads_started":1,"update_count":3500}
I20260812 06:18:10.314039  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672): perf score=18.063937
I20260812 06:18:10.373647  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.059s	user 0.020s	sys 0.039s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":21893,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:10.374199  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672): perf score=2.188937
I20260812 06:18:10.389034  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5792,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.389503  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling MajorDeltaCompactionOp(840db6eb970e4f47a411c6e14f950672): perf score=1.000000
I20260812 06:18:10.574926  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: MajorDeltaCompactionOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.185s	user 0.101s	sys 0.084s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28959067,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":563,"lbm_read_time_us":12559,"lbm_reads_lt_1ms":672,"lbm_write_time_us":29330,"lbm_writes_lt_1ms":643,"mutex_wait_us":293,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14720,"update_count":3000}
I20260812 06:18:10.577697  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672): perf score=15.087375
I20260812 06:18:10.624063  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.046s	user 0.031s	sys 0.013s Metrics: {"bytes_written":16779119,"delete_count":0,"lbm_write_time_us":19931,"lbm_writes_lt_1ms":412,"reinsert_count":0,"update_count":2045}
I20260812 06:18:10.624749  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672): perf score=2.188937
I20260812 06:18:10.639885  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.015s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3733434,"delete_count":0,"lbm_write_time_us":5163,"lbm_writes_lt_1ms":94,"reinsert_count":0,"update_count":455}
I20260812 06:18:10.640352  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling MajorDeltaCompactionOp(840db6eb970e4f47a411c6e14f950672): perf score=1.000000
I20260812 06:18:10.805091  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: MajorDeltaCompactionOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.165s	user 0.120s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856646,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":274,"lbm_read_time_us":10213,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29188,"lbm_writes_lt_1ms":543,"mutex_wait_us":45,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2500}
I20260812 06:18:10.805802  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672): perf score=14.095187
I20260812 06:18:10.856490  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.050s	user 0.030s	sys 0.015s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20823,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:10.857030  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672): perf score=2.188937
I20260812 06:18:10.866765  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3798,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.867273  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling MajorDeltaCompactionOp(840db6eb970e4f47a411c6e14f950672): perf score=1.000000
I20260812 06:18:11.040585  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: MajorDeltaCompactionOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.172s	user 0.108s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856655,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":110,"lbm_read_time_us":12298,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28617,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:18:11.041105  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672): perf score=14.095187
I20260812 06:18:11.098287  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.057s	user 0.036s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19927,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:11.098773  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672): perf score=2.188937
I20260812 06:18:11.108553  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3816,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:11.108940  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling MajorDeltaCompactionOp(840db6eb970e4f47a411c6e14f950672): perf score=1.000000
I20260812 06:18:11.283186  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: MajorDeltaCompactionOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.174s	user 0.105s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856653,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1145,"lbm_read_time_us":12721,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25846,"lbm_writes_lt_1ms":543,"mutex_wait_us":337,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7552,"update_count":2500}
I20260812 06:18:11.283751  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672): perf score=14.095187
I20260812 06:18:11.337062  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.053s	user 0.027s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":16304,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:11.337646  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672): perf score=2.188937
I20260812 06:18:11.352386  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.015s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5739,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:11.352874  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushMRSOp(840db6eb970e4f47a411c6e14f950672): perf score=1.000000
I20260812 06:18:11.384626  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushMRSOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.032s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":312,"dirs.run_wall_time_us":1392,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1456,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:11.385380  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling MajorDeltaCompactionOp(840db6eb970e4f47a411c6e14f950672): perf score=1.000000
I20260812 06:18:11.550812  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: MajorDeltaCompactionOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.165s	user 0.108s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856654,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":195,"lbm_read_time_us":11626,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27163,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:11.551378  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling LogGCOp(840db6eb970e4f47a411c6e14f950672): free 115943235 bytes of WAL
I20260812 06:18:11.551647  4458 log_reader.cc:385] T 840db6eb970e4f47a411c6e14f950672: removed 11 log segments from log reader
I20260812 06:18:11.551705  4458 log.cc:1079] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/840db6eb970e4f47a411c6e14f950672/wal-000000015 (ops 70-74)
I20260812 06:18:11.551779  4458 log.cc:1079] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/840db6eb970e4f47a411c6e14f950672/wal-000000016 (ops 75-79)
I20260812 06:18:11.551812  4458 log.cc:1079] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/840db6eb970e4f47a411c6e14f950672/wal-000000017 (ops 80-84)
I20260812 06:18:11.551834  4458 log.cc:1079] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/840db6eb970e4f47a411c6e14f950672/wal-000000018 (ops 85-89)
I20260812 06:18:11.551864  4458 log.cc:1079] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/840db6eb970e4f47a411c6e14f950672/wal-000000019 (ops 90-94)
I20260812 06:18:11.551885  4458 log.cc:1079] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/840db6eb970e4f47a411c6e14f950672/wal-000000020 (ops 95-99)
I20260812 06:18:11.551906  4458 log.cc:1079] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/840db6eb970e4f47a411c6e14f950672/wal-000000021 (ops 100-104)
I20260812 06:18:11.551928  4458 log.cc:1079] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/840db6eb970e4f47a411c6e14f950672/wal-000000022 (ops 105-109)
I20260812 06:18:11.551954  4458 log.cc:1079] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/840db6eb970e4f47a411c6e14f950672/wal-000000023 (ops 110-114)
I20260812 06:18:11.551985  4458 log.cc:1079] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/840db6eb970e4f47a411c6e14f950672/wal-000000024 (ops 115-119)
I20260812 06:18:11.552006  4458 log.cc:1079] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/840db6eb970e4f47a411c6e14f950672/wal-000000025 (ops 120-124)
I20260812 06:18:11.576294  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: LogGCOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.025s	user 0.003s	sys 0.019s Metrics: {}
I20260812 06:18:11.576789  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672): perf score=16.079562
I20260812 06:18:11.643247  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.066s	user 0.029s	sys 0.023s Metrics: {"bytes_written":18050868,"delete_count":0,"lbm_write_time_us":20594,"lbm_writes_lt_1ms":443,"reinsert_count":0,"update_count":2200}
I20260812 06:18:11.643667  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling UndoDeltaBlockGCOp(840db6eb970e4f47a411c6e14f950672): 447 bytes on disk
I20260812 06:18:11.644029  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: UndoDeltaBlockGCOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:18:11.644512  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672): perf score=5.165500
I20260812 06:18:11.659148  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":6564114,"delete_count":0,"lbm_write_time_us":6050,"lbm_writes_lt_1ms":163,"reinsert_count":0,"update_count":800}
I20260812 06:18:11.659695  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling MajorDeltaCompactionOp(840db6eb970e4f47a411c6e14f950672): perf score=1.000000
I20260812 06:18:11.840565  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: MajorDeltaCompactionOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.181s	user 0.108s	sys 0.072s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28959069,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":93,"lbm_read_time_us":14247,"lbm_reads_lt_1ms":672,"lbm_write_time_us":29442,"lbm_writes_lt_1ms":643,"mutex_wait_us":40,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":3000}
I20260812 06:18:11.841081  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672): perf score=14.095187
I20260812 06:18:11.913028  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.072s	user 0.029s	sys 0.020s Metrics: {"bytes_written":16409939,"delete_count":0,"lbm_write_time_us":39196,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:11.913638  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672): perf score=3.181125
I20260812 06:18:11.931951  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.018s	user 0.007s	sys 0.010s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7261,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:11.932379  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672): perf score=2.188937
I20260812 06:18:11.941431  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.009s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3385,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:11.941797  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling MajorDeltaCompactionOp(840db6eb970e4f47a411c6e14f950672): perf score=1.000000
I20260812 06:18:12.131649  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: MajorDeltaCompactionOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.190s	user 0.118s	sys 0.072s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28959209,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":210,"lbm_read_time_us":13192,"lbm_reads_lt_1ms":673,"lbm_write_time_us":31591,"lbm_writes_lt_1ms":643,"mutex_wait_us":39,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":3000}
I20260812 06:18:12.132277  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672): perf score=14.095187
I20260812 06:18:12.171173  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.039s	user 0.021s	sys 0.015s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":16304,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:12.171766  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672): perf score=2.188937
I20260812 06:18:12.195418  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.023s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5099,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:12.195876  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672): perf score=2.188937
I20260812 06:18:12.205729  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3899,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:12.206102  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling MajorDeltaCompactionOp(840db6eb970e4f47a411c6e14f950672): perf score=1.000000
I20260812 06:18:12.404954  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: MajorDeltaCompactionOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.199s	user 0.118s	sys 0.077s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28959183,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":114,"lbm_read_time_us":13808,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33527,"lbm_writes_lt_1ms":643,"mutex_wait_us":2,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":3000}
I20260812 06:18:12.405797  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672): perf score=14.095187
I20260812 06:18:12.447642  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.042s	user 0.021s	sys 0.018s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18555,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:12.448153  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672): perf score=2.188937
I20260812 06:18:12.459344  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.011s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4359,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:12.459932  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling MajorDeltaCompactionOp(840db6eb970e4f47a411c6e14f950672): perf score=1.000000
I20260812 06:18:12.619351  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: MajorDeltaCompactionOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.159s	user 0.116s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856653,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":576,"lbm_read_time_us":10339,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25928,"lbm_writes_lt_1ms":543,"mutex_wait_us":287,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2500}
I20260812 06:18:12.619870  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672): perf score=14.095187
I20260812 06:18:12.675096  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.055s	user 0.026s	sys 0.022s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18206,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:12.675609  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672): perf score=2.188937
I20260812 06:18:12.685629  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3870,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:12.686095  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushMRSOp(840db6eb970e4f47a411c6e14f950672): perf score=1.000000
I20260812 06:18:12.721803  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushMRSOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.036s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":217,"dirs.run_wall_time_us":1315,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1234,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:12.722615  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling LogGCOp(840db6eb970e4f47a411c6e14f950672): free 116849755 bytes of WAL
I20260812 06:18:12.722833  4458 log_reader.cc:385] T 840db6eb970e4f47a411c6e14f950672: removed 12 log segments from log reader
I20260812 06:18:12.722882  4458 log.cc:1079] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/840db6eb970e4f47a411c6e14f950672/wal-000000026 (ops 125-129)
I20260812 06:18:12.722922  4458 log.cc:1079] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/840db6eb970e4f47a411c6e14f950672/wal-000000027 (ops 130-134)
I20260812 06:18:12.722957  4458 log.cc:1079] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/840db6eb970e4f47a411c6e14f950672/wal-000000028 (ops 135-138)
I20260812 06:18:12.722987  4458 log.cc:1079] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/840db6eb970e4f47a411c6e14f950672/wal-000000029 (ops 139-143)
I20260812 06:18:12.723009  4458 log.cc:1079] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/840db6eb970e4f47a411c6e14f950672/wal-000000030 (ops 144-148)
I20260812 06:18:12.723033  4458 log.cc:1079] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/840db6eb970e4f47a411c6e14f950672/wal-000000031 (ops 149-152)
I20260812 06:18:12.723058  4458 log.cc:1079] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/840db6eb970e4f47a411c6e14f950672/wal-000000032 (ops 153-157)
I20260812 06:18:12.723081  4458 log.cc:1079] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/840db6eb970e4f47a411c6e14f950672/wal-000000033 (ops 158-162)
I20260812 06:18:12.723105  4458 log.cc:1079] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/840db6eb970e4f47a411c6e14f950672/wal-000000034 (ops 163-166)
I20260812 06:18:12.723136  4458 log.cc:1079] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/840db6eb970e4f47a411c6e14f950672/wal-000000035 (ops 167-171)
I20260812 06:18:12.723167  4458 log.cc:1079] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/840db6eb970e4f47a411c6e14f950672/wal-000000036 (ops 172-176)
I20260812 06:18:12.723198  4458 log.cc:1079] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: Deleting log segment in path: /tmp/dist-test-taskYQUbap/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515483375712-3958-0/minicluster-data/ts-0-root/wals/840db6eb970e4f47a411c6e14f950672/wal-000000037 (ops 177-181)
I20260812 06:18:12.743793  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: LogGCOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.021s	user 0.000s	sys 0.018s Metrics: {}
I20260812 06:18:12.744199  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling UndoDeltaBlockGCOp(840db6eb970e4f47a411c6e14f950672): 448 bytes on disk
I20260812 06:18:12.744685  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: UndoDeltaBlockGCOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4}
I20260812 06:18:12.745268  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672): perf score=3.181125
I20260812 06:18:12.761608  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.016s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4398,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:12.762002  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672): perf score=2.188937
I20260812 06:18:12.774974  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4764,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:12.775405  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling MajorDeltaCompactionOp(840db6eb970e4f47a411c6e14f950672): perf score=1.000000
I20260812 06:18:12.989652  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: MajorDeltaCompactionOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.214s	user 0.151s	sys 0.055s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33061707,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":82,"lbm_read_time_us":14525,"lbm_reads_lt_1ms":774,"lbm_write_time_us":35412,"lbm_writes_lt_1ms":743,"mutex_wait_us":28,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":67,"threads_started":1,"update_count":3500}
I20260812 06:18:12.990157  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672): perf score=18.063937
I20260812 06:18:13.052028  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.062s	user 0.048s	sys 0.012s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":27816,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:13.052486  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672): perf score=2.188937
I20260812 06:18:13.061923  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: FlushDeltaMemStoresOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.009s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3609,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:13.062289  4576 maintenance_manager.cc:419] P 2281a9051e074d9cbb2656cad0b09c5e: Scheduling MajorDeltaCompactionOp(840db6eb970e4f47a411c6e14f950672): perf score=1.000000
I20260812 06:18:13.147645  3958 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.555s	user 1.621s	sys 0.180s
I20260812 06:18:13.201557  3958 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.054s	user 0.002s	sys 0.000s
I20260812 06:18:13.202042  3958 tablet_server.cc:179] TabletServer@127.3.221.129:0 shutting down...
I20260812 06:18:13.245975  4458 maintenance_manager.cc:643] P 2281a9051e074d9cbb2656cad0b09c5e: MajorDeltaCompactionOp(840db6eb970e4f47a411c6e14f950672) complete. Timing: real 0.184s	user 0.130s	sys 0.050s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28959067,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":3341,"dirs.run_cpu_time_us":1418,"dirs.run_wall_time_us":9112,"lbm_read_time_us":11281,"lbm_reads_lt_1ms":668,"lbm_write_time_us":37860,"lbm_writes_lt_1ms":643,"mutex_wait_us":50,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":3000}
I20260812 06:18:13.246526  3958 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:13.246774  3958 tablet_replica.cc:333] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e: stopping tablet replica
I20260812 06:18:13.246919  3958 raft_consensus.cc:2243] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:13.247119  3958 raft_consensus.cc:2272] T 840db6eb970e4f47a411c6e14f950672 P 2281a9051e074d9cbb2656cad0b09c5e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:13.252326  3958 tablet_server.cc:196] TabletServer@127.3.221.129:0 shutdown complete.
I20260812 06:18:13.293812  3958 master.cc:562] Master@127.3.221.190:44063 shutting down...
I20260812 06:18:13.296533  3958 raft_consensus.cc:2243] T 00000000000000000000000000000000 P f0ae0fe9be4f40f8b1a8a12c2f347d36 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:13.296702  3958 raft_consensus.cc:2272] T 00000000000000000000000000000000 P f0ae0fe9be4f40f8b1a8a12c2f347d36 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:13.296767  3958 tablet_replica.cc:333] T 00000000000000000000000000000000 P f0ae0fe9be4f40f8b1a8a12c2f347d36: stopping tablet replica
I20260812 06:18:13.308885  3958 master.cc:584] Master@127.3.221.190:44063 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (4969 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (9996 ms total)

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