[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:16:38.350247 23300 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.22.193.62:41703
I20260812 06:16:38.351279 23300 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:16:38.351904 23300 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:38.358430 23306 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:38.358461 23307 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:38.358664 23300 server_base.cc:1061] running on GCE node
W20260812 06:16:38.358731 23309 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:38.359197 23300 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:38.359288 23300 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:38.359361 23300 hybrid_clock.cc:648] HybridClock initialized: now 1786515398359358 us; error 0 us; skew 500 ppm
I20260812 06:16:38.361183 23300 webserver.cc:533] Webserver started at http://127.22.193.62:35801/ using document root <none> and password file <none>
I20260812 06:16:38.361691 23300 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:38.361750 23300 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:38.361937 23300 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:38.363531 23300 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/master-0-root/instance:
uuid: "a78f6881bad74392aea1c801d027c3a3"
format_stamp: "Formatted at 2026-08-12 06:16:38 on dist-test-slave-44d2"
I20260812 06:16:38.367004 23300 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:16:38.369254 23317 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:38.370476 23300 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:38.370610 23300 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/master-0-root
uuid: "a78f6881bad74392aea1c801d027c3a3"
format_stamp: "Formatted at 2026-08-12 06:16:38 on dist-test-slave-44d2"
I20260812 06:16:38.370715 23300 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:38.386719 23300 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:38.387362 23300 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:16:38.387557 23300 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:38.395210 23300 rpc_server.cc:307] RPC server started. Bound to: 127.22.193.62:41703
I20260812 06:16:38.395215 23404 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.22.193.62:41703 every 8 connection(s)
I20260812 06:16:38.397529 23405 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:38.402976 23405 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a78f6881bad74392aea1c801d027c3a3: Bootstrap starting.
I20260812 06:16:38.405328 23405 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P a78f6881bad74392aea1c801d027c3a3: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:38.406177 23405 log.cc:826] T 00000000000000000000000000000000 P a78f6881bad74392aea1c801d027c3a3: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:38.407814 23405 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a78f6881bad74392aea1c801d027c3a3: No bootstrap required, opened a new log
I20260812 06:16:38.410516 23405 raft_consensus.cc:359] T 00000000000000000000000000000000 P a78f6881bad74392aea1c801d027c3a3 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a78f6881bad74392aea1c801d027c3a3" member_type: VOTER }
I20260812 06:16:38.410688 23405 raft_consensus.cc:385] T 00000000000000000000000000000000 P a78f6881bad74392aea1c801d027c3a3 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:38.410732 23405 raft_consensus.cc:740] T 00000000000000000000000000000000 P a78f6881bad74392aea1c801d027c3a3 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a78f6881bad74392aea1c801d027c3a3, State: Initialized, Role: FOLLOWER
I20260812 06:16:38.411355 23405 consensus_queue.cc:260] T 00000000000000000000000000000000 P a78f6881bad74392aea1c801d027c3a3 [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: "a78f6881bad74392aea1c801d027c3a3" member_type: VOTER }
I20260812 06:16:38.411500 23405 raft_consensus.cc:399] T 00000000000000000000000000000000 P a78f6881bad74392aea1c801d027c3a3 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:38.411550 23405 raft_consensus.cc:493] T 00000000000000000000000000000000 P a78f6881bad74392aea1c801d027c3a3 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:38.411649 23405 raft_consensus.cc:3060] T 00000000000000000000000000000000 P a78f6881bad74392aea1c801d027c3a3 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:38.412395 23405 raft_consensus.cc:515] T 00000000000000000000000000000000 P a78f6881bad74392aea1c801d027c3a3 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a78f6881bad74392aea1c801d027c3a3" member_type: VOTER }
I20260812 06:16:38.412864 23405 leader_election.cc:304] T 00000000000000000000000000000000 P a78f6881bad74392aea1c801d027c3a3 [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: a78f6881bad74392aea1c801d027c3a3; no voters: 
I20260812 06:16:38.413137 23405 leader_election.cc:290] T 00000000000000000000000000000000 P a78f6881bad74392aea1c801d027c3a3 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:38.413292 23410 raft_consensus.cc:2804] T 00000000000000000000000000000000 P a78f6881bad74392aea1c801d027c3a3 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:38.413574 23410 raft_consensus.cc:697] T 00000000000000000000000000000000 P a78f6881bad74392aea1c801d027c3a3 [term 1 LEADER]: Becoming Leader. State: Replica: a78f6881bad74392aea1c801d027c3a3, State: Running, Role: LEADER
I20260812 06:16:38.413980 23410 consensus_queue.cc:237] T 00000000000000000000000000000000 P a78f6881bad74392aea1c801d027c3a3 [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: "a78f6881bad74392aea1c801d027c3a3" member_type: VOTER }
I20260812 06:16:38.414229 23405 sys_catalog.cc:565] T 00000000000000000000000000000000 P a78f6881bad74392aea1c801d027c3a3 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:38.416076 23412 sys_catalog.cc:455] T 00000000000000000000000000000000 P a78f6881bad74392aea1c801d027c3a3 [sys.catalog]: SysCatalogTable state changed. Reason: New leader a78f6881bad74392aea1c801d027c3a3. Latest consensus state: current_term: 1 leader_uuid: "a78f6881bad74392aea1c801d027c3a3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a78f6881bad74392aea1c801d027c3a3" member_type: VOTER } }
I20260812 06:16:38.416059 23411 sys_catalog.cc:455] T 00000000000000000000000000000000 P a78f6881bad74392aea1c801d027c3a3 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "a78f6881bad74392aea1c801d027c3a3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a78f6881bad74392aea1c801d027c3a3" member_type: VOTER } }
I20260812 06:16:38.416208 23411 sys_catalog.cc:458] T 00000000000000000000000000000000 P a78f6881bad74392aea1c801d027c3a3 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:38.416208 23412 sys_catalog.cc:458] T 00000000000000000000000000000000 P a78f6881bad74392aea1c801d027c3a3 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:38.416553 23300 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:38.416725 23426 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:38.419200 23426 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:38.423976 23426 catalog_manager.cc:1383] Generated new cluster ID: 163b9d012add4ec3911423ddb81c157f
I20260812 06:16:38.424077 23426 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:38.433457 23426 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:38.434312 23426 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:38.440279 23426 catalog_manager.cc:6092] T 00000000000000000000000000000000 P a78f6881bad74392aea1c801d027c3a3: Generated new TSK 0
I20260812 06:16:38.440941 23426 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:38.449260 23300 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:38.451895 23432 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:38.452095 23300 server_base.cc:1061] running on GCE node
W20260812 06:16:38.452080 23437 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:16:38.451926 23433 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:38.452391 23300 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:38.452436 23300 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:38.452451 23300 hybrid_clock.cc:648] HybridClock initialized: now 1786515398452452 us; error 0 us; skew 500 ppm
I20260812 06:16:38.453408 23300 webserver.cc:533] Webserver started at http://127.22.193.1:33581/ using document root <none> and password file <none>
I20260812 06:16:38.453593 23300 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:38.453646 23300 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:38.453755 23300 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:38.454156 23300 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root/instance:
uuid: "17d5344157874907b780e029290872be"
format_stamp: "Formatted at 2026-08-12 06:16:38 on dist-test-slave-44d2"
I20260812 06:16:38.455689 23300 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:38.456748 23443 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:38.457032 23300 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:38.457135 23300 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root
uuid: "17d5344157874907b780e029290872be"
format_stamp: "Formatted at 2026-08-12 06:16:38 on dist-test-slave-44d2"
I20260812 06:16:38.457226 23300 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:38.468650 23300 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:38.469133 23300 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:38.470151 23300 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:38.471035 23300 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:38.471095 23300 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:38.471166 23300 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:38.471201 23300 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:38.477918 23300 rpc_server.cc:307] RPC server started. Bound to: 127.22.193.1:43305
I20260812 06:16:38.477952 23539 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.22.193.1:43305 every 8 connection(s)
I20260812 06:16:38.493171 23540 heartbeater.cc:344] Connected to a master server at 127.22.193.62:41703
I20260812 06:16:38.493431 23540 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:38.493942 23540 heartbeater.cc:507] Master 127.22.193.62:41703 requested a full tablet report, sending...
I20260812 06:16:38.495524 23348 ts_manager.cc:194] Registered new tserver with Master: 17d5344157874907b780e029290872be (127.22.193.1:43305)
I20260812 06:16:38.496347 23300 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.017799105s
I20260812 06:16:38.498155 23348 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:59366
I20260812 06:16:38.507283 23348 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:59372:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:16:38.523643 23477 tablet_service.cc:1511] Processing CreateTablet for tablet 4fc9f694ae5b49a5832b45b826a04160 (DEFAULT_TABLE table=heavy-update-compaction-test [id=6e0a1debbf2e4b578a105353556963a8]), partition=
I20260812 06:16:38.524130 23477 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 4fc9f694ae5b49a5832b45b826a04160. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:38.526624 23565 tablet_bootstrap.cc:492] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Bootstrap starting.
I20260812 06:16:38.527755 23565 tablet_bootstrap.cc:654] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:38.529060 23565 tablet_bootstrap.cc:492] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: No bootstrap required, opened a new log
I20260812 06:16:38.529170 23565 ts_tablet_manager.cc:1403] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:16:38.529681 23565 raft_consensus.cc:359] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "17d5344157874907b780e029290872be" member_type: VOTER last_known_addr { host: "127.22.193.1" port: 43305 } }
I20260812 06:16:38.529805 23565 raft_consensus.cc:385] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:38.529838 23565 raft_consensus.cc:740] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 17d5344157874907b780e029290872be, State: Initialized, Role: FOLLOWER
I20260812 06:16:38.530037 23565 consensus_queue.cc:260] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be [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: "17d5344157874907b780e029290872be" member_type: VOTER last_known_addr { host: "127.22.193.1" port: 43305 } }
I20260812 06:16:38.530145 23565 raft_consensus.cc:399] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:38.530215 23565 raft_consensus.cc:493] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:38.530272 23565 raft_consensus.cc:3060] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:38.531630 23565 raft_consensus.cc:515] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "17d5344157874907b780e029290872be" member_type: VOTER last_known_addr { host: "127.22.193.1" port: 43305 } }
I20260812 06:16:38.531781 23565 leader_election.cc:304] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be [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: 17d5344157874907b780e029290872be; no voters: 
I20260812 06:16:38.531991 23565 leader_election.cc:290] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:38.532140 23570 raft_consensus.cc:2804] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:38.532380 23565 ts_tablet_manager.cc:1434] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:16:38.532399 23570 raft_consensus.cc:697] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be [term 1 LEADER]: Becoming Leader. State: Replica: 17d5344157874907b780e029290872be, State: Running, Role: LEADER
I20260812 06:16:38.532665 23570 consensus_queue.cc:237] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be [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: "17d5344157874907b780e029290872be" member_type: VOTER last_known_addr { host: "127.22.193.1" port: 43305 } }
I20260812 06:16:38.533141 23540 heartbeater.cc:499] Master 127.22.193.62:41703 was elected leader, sending a full tablet report...
I20260812 06:16:38.535743 23347 catalog_manager.cc:5719] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be reported cstate change: term changed from 0 to 1, leader changed from <none> to 17d5344157874907b780e029290872be (127.22.193.1). New cstate: current_term: 1 leader_uuid: "17d5344157874907b780e029290872be" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "17d5344157874907b780e029290872be" member_type: VOTER last_known_addr { host: "127.22.193.1" port: 43305 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:38.609331 23300 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.066s	user 0.016s	sys 0.019s
I20260812 06:16:38.729280 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushMRSOp(4fc9f694ae5b49a5832b45b826a04160): perf score=6.156503
I20260812 06:16:38.880395 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushMRSOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.151s	user 0.085s	sys 0.061s Metrics: {"bytes_written":5046218,"cfile_init":1,"compiler_manager_pool.queue_time_us":68,"delete_count":0,"dirs.queue_time_us":81,"dirs.run_cpu_time_us":218,"dirs.run_wall_time_us":1007,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":52945,"lbm_writes_1-10_ms":13,"lbm_writes_lt_1ms":267,"mutex_wait_us":208,"peak_mem_usage":0,"reinsert_count":0,"rows_written":101,"spinlock_wait_cycles":97024,"update_count":615}
I20260812 06:16:38.881531 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=1.196750
I20260812 06:16:38.890756 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3159080,"delete_count":0,"lbm_write_time_us":3624,"lbm_writes_lt_1ms":80,"reinsert_count":0,"update_count":385}
I20260812 06:16:38.891223 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling MajorDeltaCompactionOp(4fc9f694ae5b49a5832b45b826a04160): perf score=1.000000
I20260812 06:16:39.106986 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: MajorDeltaCompactionOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.216s	user 0.099s	sys 0.116s Metrics: {"cfile_cache_miss":232,"cfile_cache_miss_bytes":12344537,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":824,"lbm_read_time_us":8363,"lbm_reads_lt_1ms":272,"lbm_write_time_us":78839,"lbm_writes_1-10_ms":15,"lbm_writes_lt_1ms":228,"mutex_wait_us":3,"peak_mem_usage":25836184,"reinsert_count":0,"spinlock_wait_cycles":1920,"thread_start_us":442,"threads_started":5,"update_count":1000}
I20260812 06:16:39.107715 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=6.157687
I20260812 06:16:39.170712 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.063s	user 0.013s	sys 0.048s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":44741,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:39.171414 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling UndoDeltaBlockGCOp(4fc9f694ae5b49a5832b45b826a04160): 4103815 bytes on disk
I20260812 06:16:39.171975 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: UndoDeltaBlockGCOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4}
I20260812 06:16:39.172375 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=2.188937
I20260812 06:16:39.207149 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.035s	user 0.011s	sys 0.018s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":18820,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:39.207636 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling MajorDeltaCompactionOp(4fc9f694ae5b49a5832b45b826a04160): perf score=1.000000
I20260812 06:16:39.388417 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: MajorDeltaCompactionOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.181s	user 0.098s	sys 0.074s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16446970,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1103,"lbm_read_time_us":6158,"lbm_reads_lt_1ms":364,"lbm_write_time_us":63734,"lbm_writes_1-10_ms":15,"lbm_writes_lt_1ms":328,"mutex_wait_us":57,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":1500}
I20260812 06:16:39.388988 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=10.126437
I20260812 06:16:39.447902 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.059s	user 0.028s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":37850,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:39.448419 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=2.188937
I20260812 06:16:39.494587 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.046s	user 0.009s	sys 0.025s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":25756,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:39.495158 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=2.188937
I20260812 06:16:39.534788 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.039s	user 0.011s	sys 0.020s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":22723,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:39.535504 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling MajorDeltaCompactionOp(4fc9f694ae5b49a5832b45b826a04160): perf score=1.000000
I20260812 06:16:39.851193 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: MajorDeltaCompactionOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.315s	user 0.128s	sys 0.178s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24651912,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":172,"lbm_read_time_us":10023,"lbm_reads_lt_1ms":565,"lbm_write_time_us":132650,"lbm_writes_1-10_ms":14,"lbm_writes_lt_1ms":529,"mutex_wait_us":73,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:39.851966 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=14.095187
I20260812 06:16:39.924909 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.072s	user 0.040s	sys 0.032s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":42677,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:39.925523 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=2.188937
I20260812 06:16:39.947485 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.022s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5855,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:39.948100 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling MajorDeltaCompactionOp(4fc9f694ae5b49a5832b45b826a04160): perf score=1.000000
I20260812 06:16:40.215278 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: MajorDeltaCompactionOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.267s	user 0.135s	sys 0.130s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24651791,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":916,"lbm_read_time_us":10735,"lbm_reads_lt_1ms":564,"lbm_write_time_us":136089,"lbm_writes_1-10_ms":14,"lbm_writes_lt_1ms":529,"mutex_wait_us":417,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1152,"update_count":2500}
I20260812 06:16:40.215798 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=18.063937
I20260812 06:16:40.313246 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.097s	user 0.055s	sys 0.040s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":54112,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:40.313720 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=3.181125
I20260812 06:16:40.361627 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.048s	user 0.012s	sys 0.021s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":24041,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:40.362133 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=2.188937
I20260812 06:16:40.390111 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.028s	user 0.008s	sys 0.019s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":18383,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:40.390635 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=2.188937
I20260812 06:16:40.433182 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.042s	user 0.005s	sys 0.032s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":24154,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:40.433682 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=2.188937
I20260812 06:16:40.475630 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.042s	user 0.010s	sys 0.024s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":24245,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":500}
I20260812 06:16:40.476194 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling MajorDeltaCompactionOp(4fc9f694ae5b49a5832b45b826a04160): perf score=1.000000
I20260812 06:16:41.041640 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: MajorDeltaCompactionOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.565s	user 0.251s	sys 0.313s Metrics: {"cfile_cache_miss":935,"cfile_cache_miss_bytes":41061790,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":734,"lbm_read_time_us":18809,"lbm_reads_lt_1ms":967,"lbm_write_time_us":242343,"lbm_writes_1-10_ms":14,"lbm_writes_lt_1ms":929,"peak_mem_usage":112822188,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":385,"threads_started":6,"update_count":4500}
I20260812 06:16:41.042255 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=22.032687
I20260812 06:16:41.192955 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.151s	user 0.047s	sys 0.097s Metrics: {"bytes_written":24614723,"delete_count":0,"lbm_write_time_us":84072,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":601,"reinsert_count":0,"update_count":3000}
I20260812 06:16:41.193758 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=6.157687
I20260812 06:16:41.234012 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.040s	user 0.022s	sys 0.010s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":14135,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:41.235592 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushMRSOp(4fc9f694ae5b49a5832b45b826a04160): perf score=1.000000
I20260812 06:16:41.294715 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushMRSOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.059s	user 0.035s	sys 0.000s Metrics: {"bytes_written":1357576,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":271,"dirs.run_wall_time_us":1337,"drs_written":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2578,"lbm_writes_lt_1ms":44,"peak_mem_usage":0,"rows_written":33}
I20260812 06:16:41.295576 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling LogGCOp(4fc9f694ae5b49a5832b45b826a04160): free 136687075 bytes of WAL
I20260812 06:16:41.295887 23452 log_reader.cc:385] T 4fc9f694ae5b49a5832b45b826a04160: removed 13 log segments from log reader
I20260812 06:16:41.295949 23452 log.cc:1079] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/4fc9f694ae5b49a5832b45b826a04160/wal-000000001 (ops 1-7)
I20260812 06:16:41.296020 23452 log.cc:1079] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/4fc9f694ae5b49a5832b45b826a04160/wal-000000002 (ops 8-12)
I20260812 06:16:41.296067 23452 log.cc:1079] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/4fc9f694ae5b49a5832b45b826a04160/wal-000000003 (ops 13-17)
I20260812 06:16:41.296118 23452 log.cc:1079] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/4fc9f694ae5b49a5832b45b826a04160/wal-000000004 (ops 18-22)
I20260812 06:16:41.296162 23452 log.cc:1079] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/4fc9f694ae5b49a5832b45b826a04160/wal-000000005 (ops 23-27)
I20260812 06:16:41.296211 23452 log.cc:1079] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/4fc9f694ae5b49a5832b45b826a04160/wal-000000006 (ops 28-32)
I20260812 06:16:41.296253 23452 log.cc:1079] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/4fc9f694ae5b49a5832b45b826a04160/wal-000000007 (ops 33-37)
I20260812 06:16:41.296300 23452 log.cc:1079] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/4fc9f694ae5b49a5832b45b826a04160/wal-000000008 (ops 38-42)
I20260812 06:16:41.296340 23452 log.cc:1079] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/4fc9f694ae5b49a5832b45b826a04160/wal-000000009 (ops 43-46)
I20260812 06:16:41.296379 23452 log.cc:1079] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/4fc9f694ae5b49a5832b45b826a04160/wal-000000010 (ops 47-51)
I20260812 06:16:41.296418 23452 log.cc:1079] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/4fc9f694ae5b49a5832b45b826a04160/wal-000000011 (ops 52-56)
I20260812 06:16:41.296458 23452 log.cc:1079] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/4fc9f694ae5b49a5832b45b826a04160/wal-000000012 (ops 57-61)
I20260812 06:16:41.296520 23452 log.cc:1079] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/4fc9f694ae5b49a5832b45b826a04160/wal-000000013 (ops 62-66)
I20260812 06:16:41.326339 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: LogGCOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.031s	user 0.003s	sys 0.026s Metrics: {}
I20260812 06:16:41.326817 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling UndoDeltaBlockGCOp(4fc9f694ae5b49a5832b45b826a04160): 509 bytes on disk
I20260812 06:16:41.327332 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: UndoDeltaBlockGCOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4}
I20260812 06:16:41.327947 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=7.149875
I20260812 06:16:41.355419 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.027s	user 0.014s	sys 0.010s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":12087,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:41.355916 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling LogGCOp(4fc9f694ae5b49a5832b45b826a04160): free 8767067 bytes of WAL
I20260812 06:16:41.356156 23452 log_reader.cc:385] T 4fc9f694ae5b49a5832b45b826a04160: removed 1 log segments from log reader
I20260812 06:16:41.356204 23452 log.cc:1079] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/4fc9f694ae5b49a5832b45b826a04160/wal-000000014 (ops 67-71)
I20260812 06:16:41.358134 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: LogGCOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:16:41.358525 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=2.188937
I20260812 06:16:41.376446 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.018s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4882,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:41.377074 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling MajorDeltaCompactionOp(4fc9f694ae5b49a5832b45b826a04160): perf score=1.000000
I20260812 06:16:41.752585 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: MajorDeltaCompactionOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.375s	user 0.225s	sys 0.150s Metrics: {"cfile_cache_miss":1134,"cfile_cache_miss_bytes":49266494,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1037,"lbm_read_time_us":22530,"lbm_reads_lt_1ms":1166,"lbm_write_time_us":100112,"lbm_writes_1-10_ms":5,"lbm_writes_lt_1ms":1138,"peak_mem_usage":137675332,"reinsert_count":0,"spinlock_wait_cycles":1792,"thread_start_us":430,"threads_started":6,"update_count":5500}
I20260812 06:16:41.753275 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=22.032687
I20260812 06:16:41.828552 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.075s	user 0.055s	sys 0.011s Metrics: {"bytes_written":24614720,"delete_count":0,"lbm_write_time_us":30821,"lbm_writes_lt_1ms":603,"reinsert_count":0,"update_count":3000}
I20260812 06:16:41.829102 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=6.157687
I20260812 06:16:41.867960 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.039s	user 0.011s	sys 0.009s Metrics: {"bytes_written":8205077,"delete_count":0,"lbm_write_time_us":8888,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:41.868693 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=2.188937
I20260812 06:16:41.881453 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.012s	user 0.004s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4554,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.881975 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling MajorDeltaCompactionOp(4fc9f694ae5b49a5832b45b826a04160): perf score=1.000000
I20260812 06:16:42.149569 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: MajorDeltaCompactionOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.267s	user 0.193s	sys 0.072s Metrics: {"cfile_cache_miss":933,"cfile_cache_miss_bytes":41061554,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":208,"lbm_read_time_us":22575,"lbm_reads_lt_1ms":969,"lbm_write_time_us":55757,"lbm_writes_lt_1ms":943,"mutex_wait_us":27,"peak_mem_usage":112822188,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":4500}
I20260812 06:16:42.150274 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=18.063937
I20260812 06:16:42.242905 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.092s	user 0.050s	sys 0.040s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":56856,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:42.243472 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=2.188937
I20260812 06:16:42.256728 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.013s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4991,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.257397 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling MajorDeltaCompactionOp(4fc9f694ae5b49a5832b45b826a04160): perf score=1.000000
I20260812 06:16:42.542933 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: MajorDeltaCompactionOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.285s	user 0.148s	sys 0.131s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28754207,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":863,"lbm_read_time_us":16163,"lbm_reads_lt_1ms":672,"lbm_write_time_us":73166,"lbm_writes_lt_1ms":643,"mutex_wait_us":350,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":3000}
I20260812 06:16:42.543550 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=18.063937
I20260812 06:16:42.614832 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.071s	user 0.027s	sys 0.040s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":31024,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":501,"reinsert_count":0,"update_count":2500}
I20260812 06:16:42.615388 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=2.188937
I20260812 06:16:42.631322 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5763,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.632256 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling MajorDeltaCompactionOp(4fc9f694ae5b49a5832b45b826a04160): perf score=1.000000
I20260812 06:16:42.845256 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: MajorDeltaCompactionOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.213s	user 0.134s	sys 0.078s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28754210,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":187,"lbm_read_time_us":15273,"lbm_reads_lt_1ms":672,"lbm_write_time_us":36426,"lbm_writes_lt_1ms":643,"mutex_wait_us":31,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":3000}
I20260812 06:16:42.845892 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=14.095187
I20260812 06:16:42.903409 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.057s	user 0.026s	sys 0.029s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":25424,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:42.903998 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=2.188937
I20260812 06:16:42.916013 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4500,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.916769 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushMRSOp(4fc9f694ae5b49a5832b45b826a04160): perf score=1.000000
I20260812 06:16:42.951772 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushMRSOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.035s	user 0.025s	sys 0.007s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":232,"dirs.run_wall_time_us":1253,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1683,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:42.952579 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling LogGCOp(4fc9f694ae5b49a5832b45b826a04160): free 108535504 bytes of WAL
I20260812 06:16:42.952840 23452 log_reader.cc:385] T 4fc9f694ae5b49a5832b45b826a04160: removed 11 log segments from log reader
I20260812 06:16:42.952900 23452 log.cc:1079] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/4fc9f694ae5b49a5832b45b826a04160/wal-000000015 (ops 72-76)
I20260812 06:16:42.952931 23452 log.cc:1079] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/4fc9f694ae5b49a5832b45b826a04160/wal-000000016 (ops 77-81)
I20260812 06:16:42.952992 23452 log.cc:1079] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/4fc9f694ae5b49a5832b45b826a04160/wal-000000017 (ops 82-86)
I20260812 06:16:42.953038 23452 log.cc:1079] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/4fc9f694ae5b49a5832b45b826a04160/wal-000000018 (ops 87-90)
I20260812 06:16:42.953083 23452 log.cc:1079] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/4fc9f694ae5b49a5832b45b826a04160/wal-000000019 (ops 91-95)
I20260812 06:16:42.953117 23452 log.cc:1079] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/4fc9f694ae5b49a5832b45b826a04160/wal-000000020 (ops 96-100)
I20260812 06:16:42.953156 23452 log.cc:1079] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/4fc9f694ae5b49a5832b45b826a04160/wal-000000021 (ops 101-104)
I20260812 06:16:42.953198 23452 log.cc:1079] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/4fc9f694ae5b49a5832b45b826a04160/wal-000000022 (ops 105-109)
I20260812 06:16:42.953236 23452 log.cc:1079] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/4fc9f694ae5b49a5832b45b826a04160/wal-000000023 (ops 110-114)
I20260812 06:16:42.953275 23452 log.cc:1079] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/4fc9f694ae5b49a5832b45b826a04160/wal-000000024 (ops 115-119)
I20260812 06:16:42.953312 23452 log.cc:1079] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/4fc9f694ae5b49a5832b45b826a04160/wal-000000025 (ops 120-124)
I20260812 06:16:42.979339 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: LogGCOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.027s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:16:42.980036 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling UndoDeltaBlockGCOp(4fc9f694ae5b49a5832b45b826a04160): 447 bytes on disk
I20260812 06:16:42.980789 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: UndoDeltaBlockGCOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":156,"lbm_reads_lt_1ms":4}
I20260812 06:16:42.981364 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=3.181125
I20260812 06:16:42.994021 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4985,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:42.994524 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling LogGCOp(4fc9f694ae5b49a5832b45b826a04160): free 11564877 bytes of WAL
I20260812 06:16:42.994742 23452 log_reader.cc:385] T 4fc9f694ae5b49a5832b45b826a04160: removed 1 log segments from log reader
I20260812 06:16:42.994788 23452 log.cc:1079] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/4fc9f694ae5b49a5832b45b826a04160/wal-000000026 (ops 125-128)
I20260812 06:16:42.997196 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: LogGCOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.002s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:16:42.997484 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=2.188937
I20260812 06:16:43.008335 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.011s	user 0.000s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3917,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:43.008922 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling MajorDeltaCompactionOp(4fc9f694ae5b49a5832b45b826a04160): perf score=1.000000
I20260812 06:16:43.224798 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: MajorDeltaCompactionOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.216s	user 0.135s	sys 0.071s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32856846,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":357,"lbm_read_time_us":15237,"lbm_reads_lt_1ms":774,"lbm_write_time_us":38426,"lbm_writes_lt_1ms":743,"mutex_wait_us":45,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":13568,"thread_start_us":81,"threads_started":1,"update_count":3500}
I20260812 06:16:43.225293 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=18.063937
I20260812 06:16:43.299482 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.074s	user 0.039s	sys 0.029s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":33715,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:16:43.300096 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=3.181125
I20260812 06:16:43.312273 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4631,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:43.312808 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=2.188937
I20260812 06:16:43.324219 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.011s	user 0.004s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4258,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:43.325081 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling MajorDeltaCompactionOp(4fc9f694ae5b49a5832b45b826a04160): perf score=1.000000
I20260812 06:16:43.587412 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: MajorDeltaCompactionOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.262s	user 0.154s	sys 0.105s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32856729,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":700,"lbm_read_time_us":15206,"lbm_reads_lt_1ms":773,"lbm_write_time_us":92513,"lbm_writes_1-10_ms":14,"lbm_writes_lt_1ms":729,"mutex_wait_us":313,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3500}
I20260812 06:16:43.588114 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=18.063937
I20260812 06:16:43.689045 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.101s	user 0.036s	sys 0.063s Metrics: {"bytes_written":20512319,"delete_count":0,"lbm_write_time_us":63523,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":500,"reinsert_count":0,"update_count":2500}
I20260812 06:16:43.689566 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=2.188937
I20260812 06:16:43.713975 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.024s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":8746,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.714504 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=2.188937
I20260812 06:16:43.726266 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4749,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.726738 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling MajorDeltaCompactionOp(4fc9f694ae5b49a5832b45b826a04160): perf score=1.000000
I20260812 06:16:44.108615 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: MajorDeltaCompactionOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.382s	user 0.205s	sys 0.177s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32856742,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":613,"lbm_read_time_us":18888,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":772,"lbm_write_time_us":187619,"lbm_writes_1-10_ms":13,"lbm_writes_lt_1ms":730,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1536,"thread_start_us":478,"threads_started":5,"update_count":3500}
I20260812 06:16:44.109402 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=22.032687
I20260812 06:16:44.219362 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.110s	user 0.069s	sys 0.035s Metrics: {"bytes_written":24614721,"delete_count":0,"lbm_write_time_us":62341,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":601,"reinsert_count":0,"update_count":3000}
I20260812 06:16:44.219939 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=7.149875
I20260812 06:16:44.297896 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.078s	user 0.021s	sys 0.043s Metrics: {"bytes_written":8615322,"delete_count":0,"lbm_write_time_us":46724,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:44.298502 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=6.157687
I20260812 06:16:44.364787 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.066s	user 0.026s	sys 0.035s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":43598,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:16:44.365563 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=2.188937
I20260812 06:16:44.408726 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.043s	user 0.008s	sys 0.025s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":22488,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.409307 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushMRSOp(4fc9f694ae5b49a5832b45b826a04160): perf score=1.000000
I20260812 06:16:44.446826 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushMRSOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.037s	user 0.021s	sys 0.007s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":287,"dirs.run_wall_time_us":1390,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":6012,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":37,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:44.447540 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling LogGCOp(4fc9f694ae5b49a5832b45b826a04160): free 100221546 bytes of WAL
I20260812 06:16:44.447811 23452 log_reader.cc:385] T 4fc9f694ae5b49a5832b45b826a04160: removed 10 log segments from log reader
I20260812 06:16:44.447857 23452 log.cc:1079] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/4fc9f694ae5b49a5832b45b826a04160/wal-000000027 (ops 129-133)
I20260812 06:16:44.447888 23452 log.cc:1079] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/4fc9f694ae5b49a5832b45b826a04160/wal-000000028 (ops 134-138)
I20260812 06:16:44.447928 23452 log.cc:1079] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/4fc9f694ae5b49a5832b45b826a04160/wal-000000029 (ops 139-143)
I20260812 06:16:44.447974 23452 log.cc:1079] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/4fc9f694ae5b49a5832b45b826a04160/wal-000000030 (ops 144-148)
I20260812 06:16:44.448009 23452 log.cc:1079] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/4fc9f694ae5b49a5832b45b826a04160/wal-000000031 (ops 149-153)
I20260812 06:16:44.448047 23452 log.cc:1079] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/4fc9f694ae5b49a5832b45b826a04160/wal-000000032 (ops 154-158)
I20260812 06:16:44.448081 23452 log.cc:1079] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/4fc9f694ae5b49a5832b45b826a04160/wal-000000033 (ops 159-163)
I20260812 06:16:44.448136 23452 log.cc:1079] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/4fc9f694ae5b49a5832b45b826a04160/wal-000000034 (ops 164-168)
I20260812 06:16:44.448163 23452 log.cc:1079] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/4fc9f694ae5b49a5832b45b826a04160/wal-000000035 (ops 169-172)
I20260812 06:16:44.448200 23452 log.cc:1079] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/4fc9f694ae5b49a5832b45b826a04160/wal-000000036 (ops 173-177)
I20260812 06:16:44.470810 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: LogGCOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.023s	user 0.002s	sys 0.018s Metrics: {}
I20260812 06:16:44.471331 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling UndoDeltaBlockGCOp(4fc9f694ae5b49a5832b45b826a04160): 448 bytes on disk
I20260812 06:16:44.472088 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: UndoDeltaBlockGCOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:16:44.472785 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=3.181125
I20260812 06:16:44.493793 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.021s	user 0.016s	sys 0.001s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7486,"lbm_writes_lt_1ms":113,"mutex_wait_us":27,"reinsert_count":0,"update_count":550}
I20260812 06:16:44.494410 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling LogGCOp(4fc9f694ae5b49a5832b45b826a04160): free 12018006 bytes of WAL
I20260812 06:16:44.494706 23452 log_reader.cc:385] T 4fc9f694ae5b49a5832b45b826a04160: removed 1 log segments from log reader
I20260812 06:16:44.494798 23452 log.cc:1079] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/4fc9f694ae5b49a5832b45b826a04160/wal-000000037 (ops 178-182)
I20260812 06:16:44.498071 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: LogGCOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:16:44.498385 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=2.188937
I20260812 06:16:44.512871 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.014s	user 0.009s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6550,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:44.513365 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling MajorDeltaCompactionOp(4fc9f694ae5b49a5832b45b826a04160): perf score=1.000000
I20260812 06:16:45.004588 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: MajorDeltaCompactionOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.491s	user 0.282s	sys 0.209s Metrics: {"cfile_cache_miss":1336,"cfile_cache_miss_bytes":57471555,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":6,"delta_iterators_relevant":6,"dirs.queue_time_us":304,"lbm_read_time_us":28029,"lbm_reads_lt_1ms":1368,"lbm_write_time_us":141767,"lbm_writes_1-10_ms":15,"lbm_writes_lt_1ms":1328,"mutex_wait_us":31,"peak_mem_usage":162528476,"reinsert_count":0,"spinlock_wait_cycles":3712,"thread_start_us":459,"threads_started":7,"update_count":6500}
I20260812 06:16:45.005316 23543 maintenance_manager.cc:419] P 17d5344157874907b780e029290872be: Scheduling FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160): perf score=26.001437
I20260812 06:16:45.125963 23300 heavy-update-compaction-itest.cc:229] Time spent updating: real 6.517s	user 1.862s	sys 0.139s
I20260812 06:16:45.171852 23300 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.045s	user 0.001s	sys 0.000s
I20260812 06:16:45.172569 23300 tablet_server.cc:179] TabletServer@127.22.193.1:0 shutting down...
I20260812 06:16:45.181373 23452 maintenance_manager.cc:643] P 17d5344157874907b780e029290872be: FlushDeltaMemStoresOp(4fc9f694ae5b49a5832b45b826a04160) complete. Timing: real 0.176s	user 0.060s	sys 0.115s Metrics: {"bytes_written":28717138,"delete_count":0,"lbm_write_time_us":118382,"lbm_writes_lt_1ms":703,"reinsert_count":0,"update_count":3500}
I20260812 06:16:45.181902 23300 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:45.182286 23300 tablet_replica.cc:333] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be: stopping tablet replica
I20260812 06:16:45.182514 23300 raft_consensus.cc:2243] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:45.182757 23300 raft_consensus.cc:2272] T 4fc9f694ae5b49a5832b45b826a04160 P 17d5344157874907b780e029290872be [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:45.198756 23300 tablet_server.cc:196] TabletServer@127.22.193.1:0 shutdown complete.
I20260812 06:16:45.203367 23300 master.cc:562] Master@127.22.193.62:41703 shutting down...
I20260812 06:16:45.207041 23300 raft_consensus.cc:2243] T 00000000000000000000000000000000 P a78f6881bad74392aea1c801d027c3a3 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:45.207218 23300 raft_consensus.cc:2272] T 00000000000000000000000000000000 P a78f6881bad74392aea1c801d027c3a3 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:45.207301 23300 tablet_replica.cc:333] T 00000000000000000000000000000000 P a78f6881bad74392aea1c801d027c3a3: stopping tablet replica
I20260812 06:16:45.219425 23300 master.cc:584] Master@127.22.193.62:41703 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (6963 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:16:45.332324 23300 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.22.193.62:34439
I20260812 06:16:45.332863 23300 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:45.334933 23638 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:45.334969 23636 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:45.335096 23640 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:45.335047 23300 server_base.cc:1061] running on GCE node
I20260812 06:16:45.335343 23300 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:45.335387 23300 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:45.335403 23300 hybrid_clock.cc:648] HybridClock initialized: now 1786515405335403 us; error 0 us; skew 500 ppm
I20260812 06:16:45.336243 23300 webserver.cc:533] Webserver started at http://127.22.193.62:45103/ using document root <none> and password file <none>
I20260812 06:16:45.336397 23300 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:45.336441 23300 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:45.336565 23300 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:45.336952 23300 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/master-0-root/instance:
uuid: "f2c41d6869304ac5957971ad8cf44dbf"
format_stamp: "Formatted at 2026-08-12 06:16:45 on dist-test-slave-44d2"
I20260812 06:16:45.338405 23300 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:45.339280 23647 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:45.339517 23300 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:45.339609 23300 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/master-0-root
uuid: "f2c41d6869304ac5957971ad8cf44dbf"
format_stamp: "Formatted at 2026-08-12 06:16:45 on dist-test-slave-44d2"
I20260812 06:16:45.339696 23300 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:45.346194 23300 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:45.346553 23300 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:45.351092 23300 rpc_server.cc:307] RPC server started. Bound to: 127.22.193.62:34439
I20260812 06:16:45.351570 23723 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.22.193.62:34439 every 8 connection(s)
I20260812 06:16:45.352226 23724 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:45.353994 23724 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f2c41d6869304ac5957971ad8cf44dbf: Bootstrap starting.
I20260812 06:16:45.354728 23724 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P f2c41d6869304ac5957971ad8cf44dbf: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:45.355660 23724 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P f2c41d6869304ac5957971ad8cf44dbf: No bootstrap required, opened a new log
I20260812 06:16:45.356004 23724 raft_consensus.cc:359] T 00000000000000000000000000000000 P f2c41d6869304ac5957971ad8cf44dbf [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f2c41d6869304ac5957971ad8cf44dbf" member_type: VOTER }
I20260812 06:16:45.356106 23724 raft_consensus.cc:385] T 00000000000000000000000000000000 P f2c41d6869304ac5957971ad8cf44dbf [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:45.356132 23724 raft_consensus.cc:740] T 00000000000000000000000000000000 P f2c41d6869304ac5957971ad8cf44dbf [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f2c41d6869304ac5957971ad8cf44dbf, State: Initialized, Role: FOLLOWER
I20260812 06:16:45.356240 23724 consensus_queue.cc:260] T 00000000000000000000000000000000 P f2c41d6869304ac5957971ad8cf44dbf [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: "f2c41d6869304ac5957971ad8cf44dbf" member_type: VOTER }
I20260812 06:16:45.356299 23724 raft_consensus.cc:399] T 00000000000000000000000000000000 P f2c41d6869304ac5957971ad8cf44dbf [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:45.356323 23724 raft_consensus.cc:493] T 00000000000000000000000000000000 P f2c41d6869304ac5957971ad8cf44dbf [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:45.356351 23724 raft_consensus.cc:3060] T 00000000000000000000000000000000 P f2c41d6869304ac5957971ad8cf44dbf [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:45.357069 23724 raft_consensus.cc:515] T 00000000000000000000000000000000 P f2c41d6869304ac5957971ad8cf44dbf [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f2c41d6869304ac5957971ad8cf44dbf" member_type: VOTER }
I20260812 06:16:45.357183 23724 leader_election.cc:304] T 00000000000000000000000000000000 P f2c41d6869304ac5957971ad8cf44dbf [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: f2c41d6869304ac5957971ad8cf44dbf; no voters: 
I20260812 06:16:45.357324 23724 leader_election.cc:290] T 00000000000000000000000000000000 P f2c41d6869304ac5957971ad8cf44dbf [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:45.357472 23730 raft_consensus.cc:2804] T 00000000000000000000000000000000 P f2c41d6869304ac5957971ad8cf44dbf [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:45.357689 23730 raft_consensus.cc:697] T 00000000000000000000000000000000 P f2c41d6869304ac5957971ad8cf44dbf [term 1 LEADER]: Becoming Leader. State: Replica: f2c41d6869304ac5957971ad8cf44dbf, State: Running, Role: LEADER
I20260812 06:16:45.357820 23730 consensus_queue.cc:237] T 00000000000000000000000000000000 P f2c41d6869304ac5957971ad8cf44dbf [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: "f2c41d6869304ac5957971ad8cf44dbf" member_type: VOTER }
I20260812 06:16:45.357834 23724 sys_catalog.cc:565] T 00000000000000000000000000000000 P f2c41d6869304ac5957971ad8cf44dbf [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:45.358280 23732 sys_catalog.cc:455] T 00000000000000000000000000000000 P f2c41d6869304ac5957971ad8cf44dbf [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "f2c41d6869304ac5957971ad8cf44dbf" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f2c41d6869304ac5957971ad8cf44dbf" member_type: VOTER } }
I20260812 06:16:45.358297 23733 sys_catalog.cc:455] T 00000000000000000000000000000000 P f2c41d6869304ac5957971ad8cf44dbf [sys.catalog]: SysCatalogTable state changed. Reason: New leader f2c41d6869304ac5957971ad8cf44dbf. Latest consensus state: current_term: 1 leader_uuid: "f2c41d6869304ac5957971ad8cf44dbf" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f2c41d6869304ac5957971ad8cf44dbf" member_type: VOTER } }
I20260812 06:16:45.358378 23732 sys_catalog.cc:458] T 00000000000000000000000000000000 P f2c41d6869304ac5957971ad8cf44dbf [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:45.358393 23733 sys_catalog.cc:458] T 00000000000000000000000000000000 P f2c41d6869304ac5957971ad8cf44dbf [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:45.358670 23736 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:45.359474 23736 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:45.359926 23300 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:45.361390 23736 catalog_manager.cc:1383] Generated new cluster ID: 99d7e89b5d694c269a3d040cf906e15e
I20260812 06:16:45.361462 23736 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:45.377125 23736 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:45.377669 23736 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:45.392385 23736 catalog_manager.cc:6092] T 00000000000000000000000000000000 P f2c41d6869304ac5957971ad8cf44dbf: Generated new TSK 0
I20260812 06:16:45.392607 23736 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:45.424654 23300 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:45.426923 23759 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:45.426977 23300 server_base.cc:1061] running on GCE node
W20260812 06:16:45.426986 23763 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:16:45.427006 23760 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:45.427409 23300 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:45.427480 23300 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:45.427507 23300 hybrid_clock.cc:648] HybridClock initialized: now 1786515405427507 us; error 0 us; skew 500 ppm
I20260812 06:16:45.428416 23300 webserver.cc:533] Webserver started at http://127.22.193.1:42617/ using document root <none> and password file <none>
I20260812 06:16:45.428620 23300 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:45.428696 23300 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:45.428779 23300 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:45.429210 23300 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root/instance:
uuid: "3939df33b8124321956b610096c2a913"
format_stamp: "Formatted at 2026-08-12 06:16:45 on dist-test-slave-44d2"
I20260812 06:16:45.430707 23300 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:45.431594 23770 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:45.431849 23300 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:45.431941 23300 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root
uuid: "3939df33b8124321956b610096c2a913"
format_stamp: "Formatted at 2026-08-12 06:16:45 on dist-test-slave-44d2"
I20260812 06:16:45.432034 23300 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:45.461833 23300 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:45.462288 23300 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:45.462639 23300 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:45.463163 23300 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:45.463228 23300 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:45.463289 23300 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:45.463338 23300 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:45.467926 23300 rpc_server.cc:307] RPC server started. Bound to: 127.22.193.1:37609
I20260812 06:16:45.467969 23879 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.22.193.1:37609 every 8 connection(s)
I20260812 06:16:45.478668 23880 heartbeater.cc:344] Connected to a master server at 127.22.193.62:34439
I20260812 06:16:45.478798 23880 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:45.479004 23880 heartbeater.cc:507] Master 127.22.193.62:34439 requested a full tablet report, sending...
I20260812 06:16:45.479712 23673 ts_manager.cc:194] Registered new tserver with Master: 3939df33b8124321956b610096c2a913 (127.22.193.1:37609)
I20260812 06:16:45.480535 23673 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:60108
I20260812 06:16:45.480548 23300 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012198373s
I20260812 06:16:45.487622 23673 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:60112:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:16:45.496387 23820 tablet_service.cc:1511] Processing CreateTablet for tablet 78406e0ce6f54ed6b802cd8da988f884 (DEFAULT_TABLE table=heavy-update-compaction-test [id=ea346e26bae6475a9a963fa47ba54073]), partition=
I20260812 06:16:45.496706 23820 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 78406e0ce6f54ed6b802cd8da988f884. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:45.499194 23899 tablet_bootstrap.cc:492] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Bootstrap starting.
I20260812 06:16:45.500295 23899 tablet_bootstrap.cc:654] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:45.501580 23899 tablet_bootstrap.cc:492] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: No bootstrap required, opened a new log
I20260812 06:16:45.501682 23899 ts_tablet_manager.cc:1403] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Time spent bootstrapping tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:16:45.502175 23899 raft_consensus.cc:359] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3939df33b8124321956b610096c2a913" member_type: VOTER last_known_addr { host: "127.22.193.1" port: 37609 } }
I20260812 06:16:45.502286 23899 raft_consensus.cc:385] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:45.502311 23899 raft_consensus.cc:740] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 3939df33b8124321956b610096c2a913, State: Initialized, Role: FOLLOWER
I20260812 06:16:45.502486 23899 consensus_queue.cc:260] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913 [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: "3939df33b8124321956b610096c2a913" member_type: VOTER last_known_addr { host: "127.22.193.1" port: 37609 } }
I20260812 06:16:45.502607 23899 raft_consensus.cc:399] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:45.502663 23899 raft_consensus.cc:493] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:45.502722 23899 raft_consensus.cc:3060] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:45.503480 23899 raft_consensus.cc:515] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3939df33b8124321956b610096c2a913" member_type: VOTER last_known_addr { host: "127.22.193.1" port: 37609 } }
I20260812 06:16:45.503649 23899 leader_election.cc:304] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913 [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: 3939df33b8124321956b610096c2a913; no voters: 
I20260812 06:16:45.503878 23899 leader_election.cc:290] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:45.504067 23908 raft_consensus.cc:2804] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:45.504237 23899 ts_tablet_manager.cc:1434] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:16:45.504281 23880 heartbeater.cc:499] Master 127.22.193.62:34439 was elected leader, sending a full tablet report...
I20260812 06:16:45.504323 23908 raft_consensus.cc:697] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913 [term 1 LEADER]: Becoming Leader. State: Replica: 3939df33b8124321956b610096c2a913, State: Running, Role: LEADER
I20260812 06:16:45.504541 23908 consensus_queue.cc:237] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913 [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: "3939df33b8124321956b610096c2a913" member_type: VOTER last_known_addr { host: "127.22.193.1" port: 37609 } }
I20260812 06:16:45.505996 23673 catalog_manager.cc:5719] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913 reported cstate change: term changed from 0 to 1, leader changed from <none> to 3939df33b8124321956b610096c2a913 (127.22.193.1). New cstate: current_term: 1 leader_uuid: "3939df33b8124321956b610096c2a913" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3939df33b8124321956b610096c2a913" member_type: VOTER last_known_addr { host: "127.22.193.1" port: 37609 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:45.568032 23300 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.023s	sys 0.000s
I20260812 06:16:45.718981 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushMRSOp(78406e0ce6f54ed6b802cd8da988f884): perf score=19.054940
I20260812 06:16:45.874434 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushMRSOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.155s	user 0.133s	sys 0.020s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":163,"dirs.run_cpu_time_us":205,"dirs.run_wall_time_us":877,"drs_written":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38893,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:16:45.875137 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling LogGCOp(78406e0ce6f54ed6b802cd8da988f884): free 20743880 bytes of WAL
I20260812 06:16:45.875442 23777 log_reader.cc:385] T 78406e0ce6f54ed6b802cd8da988f884: removed 2 log segments from log reader
I20260812 06:16:45.875516 23777 log.cc:1079] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/78406e0ce6f54ed6b802cd8da988f884/wal-000000001 (ops 1-6)
I20260812 06:16:45.875564 23777 log.cc:1079] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/78406e0ce6f54ed6b802cd8da988f884/wal-000000002 (ops 7-11)
I20260812 06:16:45.882015 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: LogGCOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.007s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:16:45.882426 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=3.181125
I20260812 06:16:45.911938 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.029s	user 0.003s	sys 0.016s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":5410,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:45.912611 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=2.188937
I20260812 06:16:45.922576 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3785,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:45.923032 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling MajorDeltaCompactionOp(78406e0ce6f54ed6b802cd8da988f884): perf score=1.000000
I20260812 06:16:46.116227 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: MajorDeltaCompactionOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.193s	user 0.137s	sys 0.056s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774797,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1045,"lbm_read_time_us":14817,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30249,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2688,"thread_start_us":342,"threads_started":5,"update_count":2500}
I20260812 06:16:46.117157 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=11.118625
I20260812 06:16:46.156414 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.039s	user 0.013s	sys 0.023s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":17194,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:46.157030 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=2.188937
I20260812 06:16:46.167517 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4059,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:46.168289 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling UndoDeltaBlockGCOp(78406e0ce6f54ed6b802cd8da988f884): 16411392 bytes on disk
I20260812 06:16:46.168951 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: UndoDeltaBlockGCOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":92,"lbm_reads_lt_1ms":4}
I20260812 06:16:46.169375 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling MajorDeltaCompactionOp(78406e0ce6f54ed6b802cd8da988f884): perf score=1.000000
I20260812 06:16:46.310706 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: MajorDeltaCompactionOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.141s	user 0.106s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":215,"lbm_read_time_us":9575,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26955,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":24448,"update_count":2000}
I20260812 06:16:46.311436 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=10.126437
I20260812 06:16:46.360725 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.049s	user 0.032s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17723,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:46.361198 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=2.188937
I20260812 06:16:46.372867 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.011s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4146,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.373317 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling MajorDeltaCompactionOp(78406e0ce6f54ed6b802cd8da988f884): perf score=1.000000
I20260812 06:16:46.504724 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: MajorDeltaCompactionOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.131s	user 0.110s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1461,"lbm_read_time_us":9977,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24554,"lbm_writes_lt_1ms":443,"mutex_wait_us":708,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":2000}
I20260812 06:16:46.505332 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=10.126437
I20260812 06:16:46.550262 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.045s	user 0.032s	sys 0.005s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":16665,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":1500}
I20260812 06:16:46.550829 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=2.188937
I20260812 06:16:46.566672 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.016s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5754,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.567152 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling MajorDeltaCompactionOp(78406e0ce6f54ed6b802cd8da988f884): perf score=1.000000
I20260812 06:16:46.689302 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: MajorDeltaCompactionOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.122s	user 0.102s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672280,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":702,"lbm_read_time_us":9294,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22494,"lbm_writes_lt_1ms":443,"mutex_wait_us":104,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19072,"update_count":2000}
I20260812 06:16:46.690102 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=10.126437
I20260812 06:16:46.738344 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.048s	user 0.026s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16087,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:46.738956 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=2.188937
I20260812 06:16:46.754045 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6007,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.754819 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling MajorDeltaCompactionOp(78406e0ce6f54ed6b802cd8da988f884): perf score=1.000000
I20260812 06:16:46.902261 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: MajorDeltaCompactionOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.146s	user 0.104s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"lbm_read_time_us":11099,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24988,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:16:46.903028 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=10.126437
I20260812 06:16:46.944650 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.041s	user 0.029s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18158,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:46.945173 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=2.188937
I20260812 06:16:46.957011 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4248,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.957466 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling MajorDeltaCompactionOp(78406e0ce6f54ed6b802cd8da988f884): perf score=1.000000
I20260812 06:16:47.090251 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: MajorDeltaCompactionOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.133s	user 0.112s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":990,"lbm_read_time_us":9556,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26151,"lbm_writes_lt_1ms":443,"mutex_wait_us":395,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7168,"update_count":2000}
I20260812 06:16:47.090871 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=10.126437
I20260812 06:16:47.132651 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.042s	user 0.033s	sys 0.007s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":18433,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:47.133167 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=2.188937
I20260812 06:16:47.153218 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.020s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5682,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:47.153816 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushMRSOp(78406e0ce6f54ed6b802cd8da988f884): perf score=1.000000
I20260812 06:16:47.206049 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushMRSOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.052s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":256,"dirs.run_wall_time_us":8154,"drs_written":1,"lbm_read_time_us":85,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2336,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:16:47.206770 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling LogGCOp(78406e0ce6f54ed6b802cd8da988f884): free 112239257 bytes of WAL
I20260812 06:16:47.207072 23777 log_reader.cc:385] T 78406e0ce6f54ed6b802cd8da988f884: removed 11 log segments from log reader
I20260812 06:16:47.207151 23777 log.cc:1079] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/78406e0ce6f54ed6b802cd8da988f884/wal-000000003 (ops 12-16)
I20260812 06:16:47.207197 23777 log.cc:1079] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/78406e0ce6f54ed6b802cd8da988f884/wal-000000004 (ops 17-21)
I20260812 06:16:47.207239 23777 log.cc:1079] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/78406e0ce6f54ed6b802cd8da988f884/wal-000000005 (ops 22-26)
I20260812 06:16:47.207273 23777 log.cc:1079] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/78406e0ce6f54ed6b802cd8da988f884/wal-000000006 (ops 27-30)
I20260812 06:16:47.207310 23777 log.cc:1079] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/78406e0ce6f54ed6b802cd8da988f884/wal-000000007 (ops 31-35)
I20260812 06:16:47.207357 23777 log.cc:1079] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/78406e0ce6f54ed6b802cd8da988f884/wal-000000008 (ops 36-40)
I20260812 06:16:47.207398 23777 log.cc:1079] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/78406e0ce6f54ed6b802cd8da988f884/wal-000000009 (ops 41-45)
I20260812 06:16:47.207432 23777 log.cc:1079] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/78406e0ce6f54ed6b802cd8da988f884/wal-000000010 (ops 46-50)
I20260812 06:16:47.207469 23777 log.cc:1079] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/78406e0ce6f54ed6b802cd8da988f884/wal-000000011 (ops 51-55)
I20260812 06:16:47.207505 23777 log.cc:1079] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/78406e0ce6f54ed6b802cd8da988f884/wal-000000012 (ops 56-60)
I20260812 06:16:47.207542 23777 log.cc:1079] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/78406e0ce6f54ed6b802cd8da988f884/wal-000000013 (ops 61-65)
I20260812 06:16:47.236850 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: LogGCOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.030s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:16:47.237257 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=6.157687
I20260812 06:16:47.267022 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.030s	user 0.021s	sys 0.001s Metrics: {"bytes_written":8205077,"delete_count":0,"lbm_write_time_us":10713,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:47.267514 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling LogGCOp(78406e0ce6f54ed6b802cd8da988f884): free 12017983 bytes of WAL
I20260812 06:16:47.267963 23777 log_reader.cc:385] T 78406e0ce6f54ed6b802cd8da988f884: removed 1 log segments from log reader
I20260812 06:16:47.268047 23777 log.cc:1079] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/78406e0ce6f54ed6b802cd8da988f884/wal-000000014 (ops 66-70)
I20260812 06:16:47.271164 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: LogGCOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:16:47.271538 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=2.188937
I20260812 06:16:47.287261 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.016s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6030,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:47.287801 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling MajorDeltaCompactionOp(78406e0ce6f54ed6b802cd8da988f884): perf score=1.000000
I20260812 06:16:47.482231 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: MajorDeltaCompactionOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.194s	user 0.156s	sys 0.036s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979753,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":730,"lbm_read_time_us":14400,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39128,"lbm_writes_lt_1ms":743,"mutex_wait_us":269,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":56064,"thread_start_us":126,"threads_started":1,"update_count":3500}
I20260812 06:16:47.483101 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling UndoDeltaBlockGCOp(78406e0ce6f54ed6b802cd8da988f884): 472 bytes on disk
I20260812 06:16:47.483654 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: UndoDeltaBlockGCOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":99,"lbm_reads_lt_1ms":4}
I20260812 06:16:47.484339 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=15.087375
I20260812 06:16:47.527007 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.042s	user 0.020s	sys 0.020s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":18845,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:47.527542 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=2.188937
I20260812 06:16:47.562673 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.035s	user 0.014s	sys 0.003s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":6266,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:47.563311 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=2.188937
I20260812 06:16:47.573805 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.010s	user 0.002s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4110,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:47.574301 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling MajorDeltaCompactionOp(78406e0ce6f54ed6b802cd8da988f884): perf score=1.000000
I20260812 06:16:47.781379 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: MajorDeltaCompactionOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.207s	user 0.119s	sys 0.087s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877207,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":162,"lbm_read_time_us":14000,"lbm_reads_lt_1ms":673,"lbm_write_time_us":36054,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":3000}
I20260812 06:16:47.781917 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=14.095187
I20260812 06:16:47.844559 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.062s	user 0.019s	sys 0.043s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21108,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:47.845228 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=2.188937
I20260812 06:16:47.863471 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.018s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6997,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:47.863976 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling MajorDeltaCompactionOp(78406e0ce6f54ed6b802cd8da988f884): perf score=1.000000
I20260812 06:16:48.035526 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: MajorDeltaCompactionOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.171s	user 0.119s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":200,"lbm_read_time_us":12559,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28908,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:16:48.036278 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=14.095187
I20260812 06:16:48.083817 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.047s	user 0.031s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19627,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:48.084394 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=2.188937
I20260812 06:16:48.109822 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.025s	user 0.009s	sys 0.015s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6125,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:48.110440 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling MajorDeltaCompactionOp(78406e0ce6f54ed6b802cd8da988f884): perf score=1.000000
I20260812 06:16:48.307585 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: MajorDeltaCompactionOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.197s	user 0.124s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1358,"lbm_read_time_us":13028,"lbm_reads_lt_1ms":568,"lbm_write_time_us":31289,"lbm_writes_lt_1ms":543,"mutex_wait_us":425,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5120,"update_count":2500}
I20260812 06:16:48.308313 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=14.095187
I20260812 06:16:48.361306 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.053s	user 0.026s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18606,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":5504,"update_count":2000}
I20260812 06:16:48.361888 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=2.188937
I20260812 06:16:48.377790 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6102,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:48.378428 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling MajorDeltaCompactionOp(78406e0ce6f54ed6b802cd8da988f884): perf score=1.000000
I20260812 06:16:48.566066 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: MajorDeltaCompactionOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.187s	user 0.128s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":622,"lbm_read_time_us":11351,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30126,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":2500}
I20260812 06:16:48.566795 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=14.095187
I20260812 06:16:48.617287 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.050s	user 0.030s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22614,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:48.617808 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=2.188937
I20260812 06:16:48.629886 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.012s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4589,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:48.630542 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushMRSOp(78406e0ce6f54ed6b802cd8da988f884): perf score=1.000000
I20260812 06:16:48.662025 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushMRSOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.031s	user 0.026s	sys 0.004s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":197,"dirs.run_wall_time_us":1367,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1409,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:48.662741 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling LogGCOp(78406e0ce6f54ed6b802cd8da988f884): free 112239316 bytes of WAL
I20260812 06:16:48.663003 23777 log_reader.cc:385] T 78406e0ce6f54ed6b802cd8da988f884: removed 11 log segments from log reader
I20260812 06:16:48.663081 23777 log.cc:1079] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/78406e0ce6f54ed6b802cd8da988f884/wal-000000015 (ops 71-75)
I20260812 06:16:48.663136 23777 log.cc:1079] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/78406e0ce6f54ed6b802cd8da988f884/wal-000000016 (ops 76-80)
I20260812 06:16:48.663195 23777 log.cc:1079] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/78406e0ce6f54ed6b802cd8da988f884/wal-000000017 (ops 81-85)
I20260812 06:16:48.663236 23777 log.cc:1079] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/78406e0ce6f54ed6b802cd8da988f884/wal-000000018 (ops 86-90)
I20260812 06:16:48.663276 23777 log.cc:1079] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/78406e0ce6f54ed6b802cd8da988f884/wal-000000019 (ops 91-95)
I20260812 06:16:48.663314 23777 log.cc:1079] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/78406e0ce6f54ed6b802cd8da988f884/wal-000000020 (ops 96-100)
I20260812 06:16:48.663352 23777 log.cc:1079] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/78406e0ce6f54ed6b802cd8da988f884/wal-000000021 (ops 101-105)
I20260812 06:16:48.663388 23777 log.cc:1079] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/78406e0ce6f54ed6b802cd8da988f884/wal-000000022 (ops 106-110)
I20260812 06:16:48.663425 23777 log.cc:1079] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/78406e0ce6f54ed6b802cd8da988f884/wal-000000023 (ops 111-115)
I20260812 06:16:48.663461 23777 log.cc:1079] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/78406e0ce6f54ed6b802cd8da988f884/wal-000000024 (ops 116-120)
I20260812 06:16:48.663498 23777 log.cc:1079] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/78406e0ce6f54ed6b802cd8da988f884/wal-000000025 (ops 121-124)
I20260812 06:16:48.688968 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: LogGCOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.026s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:16:48.689438 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling UndoDeltaBlockGCOp(78406e0ce6f54ed6b802cd8da988f884): 448 bytes on disk
I20260812 06:16:48.690155 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: UndoDeltaBlockGCOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":97,"lbm_reads_lt_1ms":4}
I20260812 06:16:48.690850 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=3.181125
I20260812 06:16:48.715938 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.025s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":5969,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:48.716545 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=2.188937
I20260812 06:16:48.726290 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3835,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:48.726730 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling MajorDeltaCompactionOp(78406e0ce6f54ed6b802cd8da988f884): perf score=1.000000
I20260812 06:16:48.975584 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: MajorDeltaCompactionOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.249s	user 0.163s	sys 0.072s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979739,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":324,"lbm_read_time_us":17709,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40961,"lbm_writes_lt_1ms":743,"mutex_wait_us":38,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":10240,"thread_start_us":97,"threads_started":1,"update_count":3500}
I20260812 06:16:48.976392 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=18.063937
I20260812 06:16:49.045126 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.069s	user 0.048s	sys 0.020s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":31327,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:49.045609 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=2.188937
I20260812 06:16:49.064163 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.018s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5342,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:49.064705 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling MajorDeltaCompactionOp(78406e0ce6f54ed6b802cd8da988f884): perf score=1.000000
I20260812 06:16:49.296772 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: MajorDeltaCompactionOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.232s	user 0.133s	sys 0.092s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877104,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":112,"lbm_read_time_us":14308,"lbm_reads_lt_1ms":664,"lbm_write_time_us":38884,"lbm_writes_lt_1ms":643,"mutex_wait_us":28,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3000}
I20260812 06:16:49.297456 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=18.063937
I20260812 06:16:49.384503 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.087s	user 0.045s	sys 0.019s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":31161,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:49.385208 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=2.188937
I20260812 06:16:49.401228 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5848,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:49.401909 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling MajorDeltaCompactionOp(78406e0ce6f54ed6b802cd8da988f884): perf score=1.000000
I20260812 06:16:49.602633 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: MajorDeltaCompactionOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.200s	user 0.145s	sys 0.052s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877105,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2681,"lbm_read_time_us":14028,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33372,"lbm_writes_lt_1ms":643,"mutex_wait_us":2239,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12160,"update_count":3000}
I20260812 06:16:49.603374 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=15.087375
I20260812 06:16:49.650767 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.047s	user 0.021s	sys 0.023s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":20873,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:49.651392 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=2.188937
I20260812 06:16:49.669507 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.018s	user 0.012s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5366,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:49.670006 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling MajorDeltaCompactionOp(78406e0ce6f54ed6b802cd8da988f884): perf score=1.000000
I20260812 06:16:49.832131 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: MajorDeltaCompactionOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.162s	user 0.102s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774676,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":58,"lbm_read_time_us":11801,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27830,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:16:49.832770 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=14.095187
I20260812 06:16:49.883468 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.051s	user 0.020s	sys 0.027s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":18035,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:49.884068 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=2.188937
I20260812 06:16:49.896500 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4282,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:49.897096 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling MajorDeltaCompactionOp(78406e0ce6f54ed6b802cd8da988f884): perf score=1.000000
I20260812 06:16:50.083760 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: MajorDeltaCompactionOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.186s	user 0.120s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":349,"lbm_read_time_us":14075,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31755,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":57,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:50.084807 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=14.095187
I20260812 06:16:50.156740 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.072s	user 0.027s	sys 0.036s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":28763,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:50.157327 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=2.188937
I20260812 06:16:50.168661 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4328,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:50.169129 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushMRSOp(78406e0ce6f54ed6b802cd8da988f884): perf score=1.000000
I20260812 06:16:50.209604 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushMRSOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.040s	user 0.032s	sys 0.001s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":235,"dirs.run_wall_time_us":1384,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1463,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:16:50.210335 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling LogGCOp(78406e0ce6f54ed6b802cd8da988f884): free 121006622 bytes of WAL
I20260812 06:16:50.210572 23777 log_reader.cc:385] T 78406e0ce6f54ed6b802cd8da988f884: removed 12 log segments from log reader
I20260812 06:16:50.210619 23777 log.cc:1079] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/78406e0ce6f54ed6b802cd8da988f884/wal-000000026 (ops 125-129)
I20260812 06:16:50.210650 23777 log.cc:1079] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/78406e0ce6f54ed6b802cd8da988f884/wal-000000027 (ops 130-134)
I20260812 06:16:50.210712 23777 log.cc:1079] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/78406e0ce6f54ed6b802cd8da988f884/wal-000000028 (ops 135-139)
I20260812 06:16:50.210745 23777 log.cc:1079] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/78406e0ce6f54ed6b802cd8da988f884/wal-000000029 (ops 140-144)
I20260812 06:16:50.210785 23777 log.cc:1079] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/78406e0ce6f54ed6b802cd8da988f884/wal-000000030 (ops 145-149)
I20260812 06:16:50.210847 23777 log.cc:1079] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/78406e0ce6f54ed6b802cd8da988f884/wal-000000031 (ops 150-154)
I20260812 06:16:50.210891 23777 log.cc:1079] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/78406e0ce6f54ed6b802cd8da988f884/wal-000000032 (ops 155-158)
I20260812 06:16:50.210930 23777 log.cc:1079] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/78406e0ce6f54ed6b802cd8da988f884/wal-000000033 (ops 159-163)
I20260812 06:16:50.210968 23777 log.cc:1079] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/78406e0ce6f54ed6b802cd8da988f884/wal-000000034 (ops 164-168)
I20260812 06:16:50.211004 23777 log.cc:1079] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/78406e0ce6f54ed6b802cd8da988f884/wal-000000035 (ops 169-173)
I20260812 06:16:50.211050 23777 log.cc:1079] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/78406e0ce6f54ed6b802cd8da988f884/wal-000000036 (ops 174-178)
I20260812 06:16:50.211086 23777 log.cc:1079] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: Deleting log segment in path: /tmp/dist-test-taskwWxzKN/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398339575-23300-0/minicluster-data/ts-0-root/wals/78406e0ce6f54ed6b802cd8da988f884/wal-000000037 (ops 179-183)
I20260812 06:16:50.241034 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: LogGCOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.030s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:16:50.241537 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=3.181125
I20260812 06:16:50.258896 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.017s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5086,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:50.259450 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling UndoDeltaBlockGCOp(78406e0ce6f54ed6b802cd8da988f884): 462 bytes on disk
I20260812 06:16:50.260011 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: UndoDeltaBlockGCOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:16:50.260704 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=2.188937
I20260812 06:16:50.274493 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.014s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5181,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:50.275092 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling MajorDeltaCompactionOp(78406e0ce6f54ed6b802cd8da988f884): perf score=1.000000
I20260812 06:16:50.514830 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: MajorDeltaCompactionOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.240s	user 0.152s	sys 0.087s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979741,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":266,"lbm_read_time_us":16777,"lbm_reads_lt_1ms":774,"lbm_write_time_us":42412,"lbm_writes_lt_1ms":743,"mutex_wait_us":75,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2944,"thread_start_us":85,"threads_started":1,"update_count":3500}
I20260812 06:16:50.516134 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=14.095187
I20260812 06:16:50.578130 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.062s	user 0.037s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25776,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:50.578599 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884): perf score=2.188937
I20260812 06:16:50.589180 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: FlushDeltaMemStoresOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4236,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:50.589670 23881 maintenance_manager.cc:419] P 3939df33b8124321956b610096c2a913: Scheduling MajorDeltaCompactionOp(78406e0ce6f54ed6b802cd8da988f884): perf score=1.000000
I20260812 06:16:50.680689 23300 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.113s	user 1.815s	sys 0.231s
I20260812 06:16:50.747869 23300 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.067s	user 0.001s	sys 0.000s
I20260812 06:16:50.748422 23300 tablet_server.cc:179] TabletServer@127.22.193.1:0 shutting down...
I20260812 06:16:50.764618 23777 maintenance_manager.cc:643] P 3939df33b8124321956b610096c2a913: MajorDeltaCompactionOp(78406e0ce6f54ed6b802cd8da988f884) complete. Timing: real 0.175s	user 0.115s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":407,"lbm_read_time_us":13070,"lbm_reads_lt_1ms":568,"lbm_write_time_us":31223,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":2500}
I20260812 06:16:50.765241 23300 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:50.765662 23300 tablet_replica.cc:333] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913: stopping tablet replica
I20260812 06:16:50.765810 23300 raft_consensus.cc:2243] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:50.765990 23300 raft_consensus.cc:2272] T 78406e0ce6f54ed6b802cd8da988f884 P 3939df33b8124321956b610096c2a913 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:50.783809 23300 tablet_server.cc:196] TabletServer@127.22.193.1:0 shutdown complete.
I20260812 06:16:50.810554 23300 master.cc:562] Master@127.22.193.62:34439 shutting down...
I20260812 06:16:50.814138 23300 raft_consensus.cc:2243] T 00000000000000000000000000000000 P f2c41d6869304ac5957971ad8cf44dbf [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:50.814309 23300 raft_consensus.cc:2272] T 00000000000000000000000000000000 P f2c41d6869304ac5957971ad8cf44dbf [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:50.814360 23300 tablet_replica.cc:333] T 00000000000000000000000000000000 P f2c41d6869304ac5957971ad8cf44dbf: stopping tablet replica
I20260812 06:16:50.827049 23300 master.cc:584] Master@127.22.193.62:34439 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5604 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (12569 ms total)

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