[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:18:41.809311 20395 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.19.234.254:44631
I20260812 06:18:41.810354 20395 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:18:41.810953 20395 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:41.817301 20403 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:41.817363 20407 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:41.817498 20395 server_base.cc:1061] running on GCE node
W20260812 06:18:41.817644 20404 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:41.818156 20395 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:41.818238 20395 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:41.818261 20395 hybrid_clock.cc:648] HybridClock initialized: now 1786515521818260 us; error 0 us; skew 500 ppm
I20260812 06:18:41.819952 20395 webserver.cc:533] Webserver started at http://127.19.234.254:39431/ using document root <none> and password file <none>
I20260812 06:18:41.820401 20395 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:41.820454 20395 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:41.820629 20395 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:41.822139 20395 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/master-0-root/instance:
uuid: "af0959f893d04287af9002b9a1d9ca42"
format_stamp: "Formatted at 2026-08-12 06:18:41 on dist-test-slave-c12x"
I20260812 06:18:41.825778 20395 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:18:41.827819 20416 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:41.828963 20395 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:41.829082 20395 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/master-0-root
uuid: "af0959f893d04287af9002b9a1d9ca42"
format_stamp: "Formatted at 2026-08-12 06:18:41 on dist-test-slave-c12x"
I20260812 06:18:41.829165 20395 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:41.850534 20395 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:41.851130 20395 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:18:41.851269 20395 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:41.858983 20395 rpc_server.cc:307] RPC server started. Bound to: 127.19.234.254:44631
I20260812 06:18:41.858999 20498 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.19.234.254:44631 every 8 connection(s)
I20260812 06:18:41.861171 20499 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:41.866354 20499 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P af0959f893d04287af9002b9a1d9ca42: Bootstrap starting.
I20260812 06:18:41.868702 20499 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P af0959f893d04287af9002b9a1d9ca42: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:41.869652 20499 log.cc:826] T 00000000000000000000000000000000 P af0959f893d04287af9002b9a1d9ca42: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:41.871569 20499 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P af0959f893d04287af9002b9a1d9ca42: No bootstrap required, opened a new log
I20260812 06:18:41.874459 20499 raft_consensus.cc:359] T 00000000000000000000000000000000 P af0959f893d04287af9002b9a1d9ca42 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "af0959f893d04287af9002b9a1d9ca42" member_type: VOTER }
I20260812 06:18:41.874670 20499 raft_consensus.cc:385] T 00000000000000000000000000000000 P af0959f893d04287af9002b9a1d9ca42 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:41.874768 20499 raft_consensus.cc:740] T 00000000000000000000000000000000 P af0959f893d04287af9002b9a1d9ca42 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: af0959f893d04287af9002b9a1d9ca42, State: Initialized, Role: FOLLOWER
I20260812 06:18:41.875352 20499 consensus_queue.cc:260] T 00000000000000000000000000000000 P af0959f893d04287af9002b9a1d9ca42 [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: "af0959f893d04287af9002b9a1d9ca42" member_type: VOTER }
I20260812 06:18:41.875564 20499 raft_consensus.cc:399] T 00000000000000000000000000000000 P af0959f893d04287af9002b9a1d9ca42 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:41.875648 20499 raft_consensus.cc:493] T 00000000000000000000000000000000 P af0959f893d04287af9002b9a1d9ca42 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:41.875802 20499 raft_consensus.cc:3060] T 00000000000000000000000000000000 P af0959f893d04287af9002b9a1d9ca42 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:41.876624 20499 raft_consensus.cc:515] T 00000000000000000000000000000000 P af0959f893d04287af9002b9a1d9ca42 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "af0959f893d04287af9002b9a1d9ca42" member_type: VOTER }
I20260812 06:18:41.877065 20499 leader_election.cc:304] T 00000000000000000000000000000000 P af0959f893d04287af9002b9a1d9ca42 [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: af0959f893d04287af9002b9a1d9ca42; no voters: 
I20260812 06:18:41.877388 20499 leader_election.cc:290] T 00000000000000000000000000000000 P af0959f893d04287af9002b9a1d9ca42 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:41.877542 20504 raft_consensus.cc:2804] T 00000000000000000000000000000000 P af0959f893d04287af9002b9a1d9ca42 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:41.877800 20504 raft_consensus.cc:697] T 00000000000000000000000000000000 P af0959f893d04287af9002b9a1d9ca42 [term 1 LEADER]: Becoming Leader. State: Replica: af0959f893d04287af9002b9a1d9ca42, State: Running, Role: LEADER
I20260812 06:18:41.878242 20504 consensus_queue.cc:237] T 00000000000000000000000000000000 P af0959f893d04287af9002b9a1d9ca42 [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: "af0959f893d04287af9002b9a1d9ca42" member_type: VOTER }
I20260812 06:18:41.878358 20499 sys_catalog.cc:565] T 00000000000000000000000000000000 P af0959f893d04287af9002b9a1d9ca42 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:41.880220 20505 sys_catalog.cc:455] T 00000000000000000000000000000000 P af0959f893d04287af9002b9a1d9ca42 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "af0959f893d04287af9002b9a1d9ca42" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "af0959f893d04287af9002b9a1d9ca42" member_type: VOTER } }
I20260812 06:18:41.880358 20505 sys_catalog.cc:458] T 00000000000000000000000000000000 P af0959f893d04287af9002b9a1d9ca42 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:41.880221 20506 sys_catalog.cc:455] T 00000000000000000000000000000000 P af0959f893d04287af9002b9a1d9ca42 [sys.catalog]: SysCatalogTable state changed. Reason: New leader af0959f893d04287af9002b9a1d9ca42. Latest consensus state: current_term: 1 leader_uuid: "af0959f893d04287af9002b9a1d9ca42" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "af0959f893d04287af9002b9a1d9ca42" member_type: VOTER } }
I20260812 06:18:41.880414 20506 sys_catalog.cc:458] T 00000000000000000000000000000000 P af0959f893d04287af9002b9a1d9ca42 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:41.880692 20530 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:41.880769 20395 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:41.882845 20530 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:41.887240 20530 catalog_manager.cc:1383] Generated new cluster ID: d2f922d21b2341f8a7f792b4ebf530e5
I20260812 06:18:41.887307 20530 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:41.905241 20530 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:41.906483 20530 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:41.926285 20530 catalog_manager.cc:6092] T 00000000000000000000000000000000 P af0959f893d04287af9002b9a1d9ca42: Generated new TSK 0
I20260812 06:18:41.927052 20530 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:41.945814 20395 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:41.948967 20537 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:41.949180 20540 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:41.949313 20542 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:41.949478 20395 server_base.cc:1061] running on GCE node
I20260812 06:18:41.949710 20395 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:41.949752 20395 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:41.949769 20395 hybrid_clock.cc:648] HybridClock initialized: now 1786515521949768 us; error 0 us; skew 500 ppm
I20260812 06:18:41.950853 20395 webserver.cc:533] Webserver started at http://127.19.234.193:40343/ using document root <none> and password file <none>
I20260812 06:18:41.951061 20395 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:41.951110 20395 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:41.951215 20395 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:41.951712 20395 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/instance:
uuid: "1c4e8b6f09664ee381cd232317f44f58"
format_stamp: "Formatted at 2026-08-12 06:18:41 on dist-test-slave-c12x"
I20260812 06:18:41.953287 20395 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:41.954355 20553 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:41.954640 20395 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:41.954732 20395 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root
uuid: "1c4e8b6f09664ee381cd232317f44f58"
format_stamp: "Formatted at 2026-08-12 06:18:41 on dist-test-slave-c12x"
I20260812 06:18:41.954813 20395 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:41.973569 20395 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:41.974200 20395 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:41.974692 20395 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:41.975680 20395 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:41.975759 20395 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:41.975833 20395 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:41.975878 20395 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:41.982627 20395 rpc_server.cc:307] RPC server started. Bound to: 127.19.234.193:36429
I20260812 06:18:41.982887 20664 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.19.234.193:36429 every 8 connection(s)
I20260812 06:18:41.993400 20665 heartbeater.cc:344] Connected to a master server at 127.19.234.254:44631
I20260812 06:18:41.993681 20665 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:41.994223 20665 heartbeater.cc:507] Master 127.19.234.254:44631 requested a full tablet report, sending...
I20260812 06:18:41.995823 20445 ts_manager.cc:194] Registered new tserver with Master: 1c4e8b6f09664ee381cd232317f44f58 (127.19.234.193:36429)
I20260812 06:18:41.996313 20395 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012861269s
I20260812 06:18:41.997386 20445 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:53454
I20260812 06:18:42.007141 20445 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:53464:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:42.023496 20599 tablet_service.cc:1511] Processing CreateTablet for tablet 24cb268947644fd2a4d176f506680e0c (DEFAULT_TABLE table=heavy-update-compaction-test [id=958f162d886744fa894dd41d5513bc3d]), partition=
I20260812 06:18:42.024044 20599 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 24cb268947644fd2a4d176f506680e0c. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:42.026438 20680 tablet_bootstrap.cc:492] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Bootstrap starting.
I20260812 06:18:42.027354 20680 tablet_bootstrap.cc:654] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:42.028755 20680 tablet_bootstrap.cc:492] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: No bootstrap required, opened a new log
I20260812 06:18:42.028903 20680 ts_tablet_manager.cc:1403] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:42.029460 20680 raft_consensus.cc:359] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1c4e8b6f09664ee381cd232317f44f58" member_type: VOTER last_known_addr { host: "127.19.234.193" port: 36429 } }
I20260812 06:18:42.029599 20680 raft_consensus.cc:385] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:42.029649 20680 raft_consensus.cc:740] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 1c4e8b6f09664ee381cd232317f44f58, State: Initialized, Role: FOLLOWER
I20260812 06:18:42.029791 20680 consensus_queue.cc:260] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58 [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: "1c4e8b6f09664ee381cd232317f44f58" member_type: VOTER last_known_addr { host: "127.19.234.193" port: 36429 } }
I20260812 06:18:42.029901 20680 raft_consensus.cc:399] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:42.029949 20680 raft_consensus.cc:493] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:42.030004 20680 raft_consensus.cc:3060] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:42.031117 20680 raft_consensus.cc:515] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1c4e8b6f09664ee381cd232317f44f58" member_type: VOTER last_known_addr { host: "127.19.234.193" port: 36429 } }
I20260812 06:18:42.031654 20680 leader_election.cc:304] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58 [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: 1c4e8b6f09664ee381cd232317f44f58; no voters: 
I20260812 06:18:42.032009 20680 leader_election.cc:290] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:42.032155 20684 raft_consensus.cc:2804] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:42.032539 20680 ts_tablet_manager.cc:1434] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Time spent starting tablet: real 0.004s	user 0.003s	sys 0.000s
I20260812 06:18:42.033049 20665 heartbeater.cc:499] Master 127.19.234.254:44631 was elected leader, sending a full tablet report...
I20260812 06:18:42.033089 20684 raft_consensus.cc:697] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58 [term 1 LEADER]: Becoming Leader. State: Replica: 1c4e8b6f09664ee381cd232317f44f58, State: Running, Role: LEADER
I20260812 06:18:42.033243 20684 consensus_queue.cc:237] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58 [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: "1c4e8b6f09664ee381cd232317f44f58" member_type: VOTER last_known_addr { host: "127.19.234.193" port: 36429 } }
I20260812 06:18:42.036052 20445 catalog_manager.cc:5719] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58 reported cstate change: term changed from 0 to 1, leader changed from <none> to 1c4e8b6f09664ee381cd232317f44f58 (127.19.234.193). New cstate: current_term: 1 leader_uuid: "1c4e8b6f09664ee381cd232317f44f58" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1c4e8b6f09664ee381cd232317f44f58" member_type: VOTER last_known_addr { host: "127.19.234.193" port: 36429 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:42.103816 20395 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.057s	user 0.015s	sys 0.012s
I20260812 06:18:42.234001 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushMRSOp(24cb268947644fd2a4d176f506680e0c): perf score=18.062753
I20260812 06:18:42.392658 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushMRSOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.158s	user 0.123s	sys 0.032s Metrics: {"bytes_written":8615323,"cfile_init":1,"compiler_manager_pool.queue_time_us":462,"delete_count":0,"dirs.queue_time_us":46,"dirs.run_cpu_time_us":182,"dirs.run_wall_time_us":698,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40686,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":666,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":102,"threads_started":1,"update_count":1050}
I20260812 06:18:42.393653 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling LogGCOp(24cb268947644fd2a4d176f506680e0c): free 20743880 bytes of WAL
I20260812 06:18:42.393950 20565 log_reader.cc:385] T 24cb268947644fd2a4d176f506680e0c: removed 2 log segments from log reader
I20260812 06:18:42.394035 20565 log.cc:1079] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/24cb268947644fd2a4d176f506680e0c/wal-000000001 (ops 1-6)
I20260812 06:18:42.394109 20565 log.cc:1079] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/24cb268947644fd2a4d176f506680e0c/wal-000000002 (ops 7-11)
I20260812 06:18:42.399590 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: LogGCOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.006s	user 0.000s	sys 0.006s Metrics: {}
I20260812 06:18:42.400034 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling UndoDeltaBlockGCOp(24cb268947644fd2a4d176f506680e0c): 16411398 bytes on disk
I20260812 06:18:42.400729 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: UndoDeltaBlockGCOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":96,"lbm_reads_lt_1ms":4}
I20260812 06:18:42.401343 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=2.188937
I20260812 06:18:42.424605 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.023s	user 0.004s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5356,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:42.425127 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=2.188937
I20260812 06:18:42.436321 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4140,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.436779 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling MajorDeltaCompactionOp(24cb268947644fd2a4d176f506680e0c): perf score=1.000000
I20260812 06:18:42.575340 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: MajorDeltaCompactionOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.138s	user 0.108s	sys 0.030s Metrics: {"cfile_cache_miss":433,"cfile_cache_miss_bytes":20672387,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":596,"lbm_read_time_us":8495,"lbm_reads_lt_1ms":469,"lbm_write_time_us":25684,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11392,"thread_start_us":270,"threads_started":5,"update_count":2000}
I20260812 06:18:42.576004 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=10.126437
I20260812 06:18:42.621259 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.045s	user 0.014s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14385,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":1500}
I20260812 06:18:42.621704 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=2.188937
I20260812 06:18:42.634771 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.013s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4285,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.635262 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling MajorDeltaCompactionOp(24cb268947644fd2a4d176f506680e0c): perf score=1.000000
I20260812 06:18:42.753417 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: MajorDeltaCompactionOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.118s	user 0.069s	sys 0.049s 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":1005,"lbm_read_time_us":8536,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23489,"lbm_writes_lt_1ms":443,"mutex_wait_us":267,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2000}
I20260812 06:18:42.754058 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=10.126437
I20260812 06:18:42.792572 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.038s	user 0.032s	sys 0.003s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15981,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:42.793114 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=2.188937
I20260812 06:18:42.804709 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102663,"delete_count":0,"lbm_write_time_us":4530,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.806023 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling MajorDeltaCompactionOp(24cb268947644fd2a4d176f506680e0c): perf score=1.000000
I20260812 06:18:42.930630 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: MajorDeltaCompactionOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.124s	user 0.114s	sys 0.008s 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":3057,"lbm_read_time_us":8278,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22478,"lbm_writes_lt_1ms":443,"mutex_wait_us":2416,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13568,"update_count":2000}
I20260812 06:18:42.931290 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=10.126437
I20260812 06:18:42.978245 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.047s	user 0.024s	sys 0.019s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":21102,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":300,"reinsert_count":0,"update_count":1500}
I20260812 06:18:42.978811 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=2.188937
I20260812 06:18:42.996254 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.017s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6487,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.996858 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling MajorDeltaCompactionOp(24cb268947644fd2a4d176f506680e0c): perf score=1.000000
I20260812 06:18:43.144594 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: MajorDeltaCompactionOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.148s	user 0.098s	sys 0.047s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":169,"lbm_read_time_us":7716,"lbm_reads_lt_1ms":468,"lbm_write_time_us":26808,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":2000}
I20260812 06:18:43.145325 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=11.118625
I20260812 06:18:43.183799 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.038s	user 0.026s	sys 0.012s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":17497,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:43.184315 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=2.188937
I20260812 06:18:43.195817 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.011s	user 0.003s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4505,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:43.196532 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling MajorDeltaCompactionOp(24cb268947644fd2a4d176f506680e0c): perf score=1.000000
I20260812 06:18:43.317579 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: MajorDeltaCompactionOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.121s	user 0.108s	sys 0.012s 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":624,"lbm_read_time_us":7983,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24200,"lbm_writes_lt_1ms":443,"mutex_wait_us":294,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:18:43.318274 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=10.126437
I20260812 06:18:43.351989 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.034s	user 0.016s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14161,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1500}
I20260812 06:18:43.352798 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=2.188937
I20260812 06:18:43.380703 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.028s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5839,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.381115 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=2.188937
I20260812 06:18:43.391533 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3919,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.391956 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling MajorDeltaCompactionOp(24cb268947644fd2a4d176f506680e0c): perf score=1.000000
I20260812 06:18:43.536437 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: MajorDeltaCompactionOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.144s	user 0.132s	sys 0.012s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774807,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":292,"lbm_read_time_us":8792,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31073,"lbm_writes_lt_1ms":543,"mutex_wait_us":70,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:18:43.537184 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=10.126437
I20260812 06:18:43.571022 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.034s	user 0.030s	sys 0.000s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14187,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:43.571638 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=2.188937
I20260812 06:18:43.595422 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.024s	user 0.000s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6020,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.596089 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushMRSOp(24cb268947644fd2a4d176f506680e0c): perf score=1.000000
I20260812 06:18:43.632954 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushMRSOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.037s	user 0.030s	sys 0.004s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":278,"dirs.run_wall_time_us":1555,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1792,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:43.633813 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling LogGCOp(24cb268947644fd2a4d176f506680e0c): free 112239253 bytes of WAL
I20260812 06:18:43.634060 20565 log_reader.cc:385] T 24cb268947644fd2a4d176f506680e0c: removed 11 log segments from log reader
I20260812 06:18:43.634126 20565 log.cc:1079] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/24cb268947644fd2a4d176f506680e0c/wal-000000003 (ops 12-16)
I20260812 06:18:43.634183 20565 log.cc:1079] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/24cb268947644fd2a4d176f506680e0c/wal-000000004 (ops 17-21)
I20260812 06:18:43.634227 20565 log.cc:1079] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/24cb268947644fd2a4d176f506680e0c/wal-000000005 (ops 22-26)
I20260812 06:18:43.634281 20565 log.cc:1079] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/24cb268947644fd2a4d176f506680e0c/wal-000000006 (ops 27-31)
I20260812 06:18:43.634327 20565 log.cc:1079] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/24cb268947644fd2a4d176f506680e0c/wal-000000007 (ops 32-36)
I20260812 06:18:43.634377 20565 log.cc:1079] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/24cb268947644fd2a4d176f506680e0c/wal-000000008 (ops 37-41)
I20260812 06:18:43.634440 20565 log.cc:1079] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/24cb268947644fd2a4d176f506680e0c/wal-000000009 (ops 42-46)
I20260812 06:18:43.634492 20565 log.cc:1079] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/24cb268947644fd2a4d176f506680e0c/wal-000000010 (ops 47-51)
I20260812 06:18:43.634542 20565 log.cc:1079] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/24cb268947644fd2a4d176f506680e0c/wal-000000011 (ops 52-56)
I20260812 06:18:43.634590 20565 log.cc:1079] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/24cb268947644fd2a4d176f506680e0c/wal-000000012 (ops 57-60)
I20260812 06:18:43.634632 20565 log.cc:1079] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/24cb268947644fd2a4d176f506680e0c/wal-000000013 (ops 61-65)
I20260812 06:18:43.659751 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: LogGCOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.026s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:43.660238 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling UndoDeltaBlockGCOp(24cb268947644fd2a4d176f506680e0c): 472 bytes on disk
I20260812 06:18:43.660670 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: UndoDeltaBlockGCOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:18:43.661123 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=5.165500
I20260812 06:18:43.681087 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.020s	user 0.005s	sys 0.013s Metrics: {"bytes_written":6892306,"delete_count":0,"lbm_write_time_us":8521,"lbm_writes_lt_1ms":171,"reinsert_count":0,"update_count":840}
I20260812 06:18:43.681552 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling LogGCOp(24cb268947644fd2a4d176f506680e0c): free 8767174 bytes of WAL
I20260812 06:18:43.681770 20565 log_reader.cc:385] T 24cb268947644fd2a4d176f506680e0c: removed 1 log segments from log reader
I20260812 06:18:43.681811 20565 log.cc:1079] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/24cb268947644fd2a4d176f506680e0c/wal-000000014 (ops 66-70)
I20260812 06:18:43.683856 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: LogGCOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.002s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:43.684621 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=1.000000
I20260812 06:18:43.689940 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.005s	user 0.003s	sys 0.001s Metrics: {"bytes_written":1312952,"delete_count":0,"lbm_write_time_us":1516,"lbm_writes_lt_1ms":35,"reinsert_count":0,"update_count":160}
I20260812 06:18:43.690348 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling MajorDeltaCompactionOp(24cb268947644fd2a4d176f506680e0c): perf score=1.000000
I20260812 06:18:43.871831 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: MajorDeltaCompactionOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.181s	user 0.124s	sys 0.052s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877274,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1627,"lbm_read_time_us":12332,"lbm_reads_lt_1ms":674,"lbm_write_time_us":38231,"lbm_writes_lt_1ms":643,"mutex_wait_us":573,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6784,"thread_start_us":77,"threads_started":1,"update_count":3000}
I20260812 06:18:43.872764 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=14.095187
I20260812 06:18:43.933544 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.061s	user 0.018s	sys 0.040s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":26544,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:43.934010 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=2.188937
I20260812 06:18:43.946780 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.013s	user 0.000s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4829,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.947216 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling MajorDeltaCompactionOp(24cb268947644fd2a4d176f506680e0c): perf score=1.000000
I20260812 06:18:44.103667 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: MajorDeltaCompactionOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.156s	user 0.133s	sys 0.015s 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":411,"lbm_read_time_us":10494,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31698,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":153344,"update_count":2500}
I20260812 06:18:44.104447 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=11.118625
I20260812 06:18:44.148756 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.044s	user 0.032s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18354,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:18:44.149353 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=2.188937
I20260812 06:18:44.164690 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.015s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4501,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:44.165221 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling MajorDeltaCompactionOp(24cb268947644fd2a4d176f506680e0c): perf score=1.000000
I20260812 06:18:44.306756 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: MajorDeltaCompactionOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.141s	user 0.097s	sys 0.042s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":258,"lbm_read_time_us":8258,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24721,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:44.307512 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=11.118625
I20260812 06:18:44.357100 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.049s	user 0.030s	sys 0.018s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17335,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:44.357661 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=2.188937
I20260812 06:18:44.373176 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.015s	user 0.008s	sys 0.006s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5523,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:44.373783 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling MajorDeltaCompactionOp(24cb268947644fd2a4d176f506680e0c): perf score=1.000000
I20260812 06:18:44.531247 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: MajorDeltaCompactionOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.157s	user 0.109s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":201,"lbm_read_time_us":10948,"lbm_reads_lt_1ms":468,"lbm_write_time_us":26625,"lbm_writes_lt_1ms":443,"mutex_wait_us":29,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:18:44.531905 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=10.126437
I20260812 06:18:44.572259 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.040s	user 0.020s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17948,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:44.572834 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=2.188937
I20260812 06:18:44.586504 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.013s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5007,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.587129 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling MajorDeltaCompactionOp(24cb268947644fd2a4d176f506680e0c): perf score=1.000000
I20260812 06:18:44.704361 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: MajorDeltaCompactionOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.117s	user 0.097s	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":287,"lbm_read_time_us":7829,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23388,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":2000}
I20260812 06:18:44.705262 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=10.126437
I20260812 06:18:44.748392 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.043s	user 0.029s	sys 0.011s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":18339,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":1500}
I20260812 06:18:44.748986 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=2.188937
I20260812 06:18:44.759649 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4090,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.760275 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling MajorDeltaCompactionOp(24cb268947644fd2a4d176f506680e0c): perf score=1.000000
I20260812 06:18:44.891615 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: MajorDeltaCompactionOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.131s	user 0.120s	sys 0.005s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":503,"lbm_read_time_us":7378,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25419,"lbm_writes_lt_1ms":443,"mutex_wait_us":107,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2000}
I20260812 06:18:44.892330 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=10.126437
I20260812 06:18:44.940078 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.048s	user 0.031s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16892,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:44.940593 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=2.188937
I20260812 06:18:44.952186 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4277,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.953064 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling MajorDeltaCompactionOp(24cb268947644fd2a4d176f506680e0c): perf score=1.000000
I20260812 06:18:45.096796 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: MajorDeltaCompactionOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.144s	user 0.100s	sys 0.043s 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":152,"lbm_read_time_us":10657,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25729,"lbm_writes_lt_1ms":443,"mutex_wait_us":51,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2000}
I20260812 06:18:45.097536 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=10.126437
I20260812 06:18:45.148674 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.051s	user 0.026s	sys 0.023s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":18592,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:45.149304 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=2.188937
I20260812 06:18:45.166472 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.017s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6466,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.167163 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushMRSOp(24cb268947644fd2a4d176f506680e0c): perf score=1.000000
I20260812 06:18:45.207741 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushMRSOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.040s	user 0.035s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":79,"dirs.run_cpu_time_us":200,"dirs.run_wall_time_us":1290,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1609,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:45.208455 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling LogGCOp(24cb268947644fd2a4d176f506680e0c): free 124257200 bytes of WAL
I20260812 06:18:45.208683 20565 log_reader.cc:385] T 24cb268947644fd2a4d176f506680e0c: removed 12 log segments from log reader
I20260812 06:18:45.208736 20565 log.cc:1079] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/24cb268947644fd2a4d176f506680e0c/wal-000000015 (ops 71-74)
I20260812 06:18:45.208765 20565 log.cc:1079] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/24cb268947644fd2a4d176f506680e0c/wal-000000016 (ops 75-79)
I20260812 06:18:45.208827 20565 log.cc:1079] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/24cb268947644fd2a4d176f506680e0c/wal-000000017 (ops 80-84)
I20260812 06:18:45.208871 20565 log.cc:1079] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/24cb268947644fd2a4d176f506680e0c/wal-000000018 (ops 85-89)
I20260812 06:18:45.208927 20565 log.cc:1079] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/24cb268947644fd2a4d176f506680e0c/wal-000000019 (ops 90-94)
I20260812 06:18:45.208983 20565 log.cc:1079] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/24cb268947644fd2a4d176f506680e0c/wal-000000020 (ops 95-99)
I20260812 06:18:45.209026 20565 log.cc:1079] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/24cb268947644fd2a4d176f506680e0c/wal-000000021 (ops 100-104)
I20260812 06:18:45.209084 20565 log.cc:1079] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/24cb268947644fd2a4d176f506680e0c/wal-000000022 (ops 105-109)
I20260812 06:18:45.209126 20565 log.cc:1079] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/24cb268947644fd2a4d176f506680e0c/wal-000000023 (ops 110-114)
I20260812 06:18:45.209182 20565 log.cc:1079] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/24cb268947644fd2a4d176f506680e0c/wal-000000024 (ops 115-119)
I20260812 06:18:45.209224 20565 log.cc:1079] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/24cb268947644fd2a4d176f506680e0c/wal-000000025 (ops 120-124)
I20260812 06:18:45.209264 20565 log.cc:1079] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/24cb268947644fd2a4d176f506680e0c/wal-000000026 (ops 125-129)
I20260812 06:18:45.236871 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: LogGCOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.028s	user 0.001s	sys 0.026s Metrics: {}
I20260812 06:18:45.237277 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=2.188937
I20260812 06:18:45.254750 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.017s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5370,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.255249 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=2.188937
I20260812 06:18:45.267755 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.012s	user 0.008s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4498,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.268491 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling UndoDeltaBlockGCOp(24cb268947644fd2a4d176f506680e0c): 473 bytes on disk
I20260812 06:18:45.269049 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: UndoDeltaBlockGCOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":85,"lbm_reads_lt_1ms":4}
I20260812 06:18:45.269783 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling MajorDeltaCompactionOp(24cb268947644fd2a4d176f506680e0c): perf score=1.000000
I20260812 06:18:45.472200 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: MajorDeltaCompactionOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.202s	user 0.131s	sys 0.071s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877341,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":828,"lbm_read_time_us":13677,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34551,"lbm_writes_lt_1ms":643,"mutex_wait_us":318,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":19072,"thread_start_us":83,"threads_started":1,"update_count":3000}
I20260812 06:18:45.472965 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=14.095187
I20260812 06:18:45.528398 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.055s	user 0.036s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22277,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.528909 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=2.188937
I20260812 06:18:45.540336 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4096,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.540959 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling MajorDeltaCompactionOp(24cb268947644fd2a4d176f506680e0c): perf score=1.000000
I20260812 06:18:45.729110 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: MajorDeltaCompactionOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.187s	user 0.127s	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":197,"lbm_read_time_us":10775,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34940,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":67072,"update_count":2500}
I20260812 06:18:45.729841 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=14.095187
I20260812 06:18:45.786355 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.056s	user 0.035s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22676,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.786916 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=2.188937
I20260812 06:18:45.799122 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4614,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.799898 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling MajorDeltaCompactionOp(24cb268947644fd2a4d176f506680e0c): perf score=1.000000
I20260812 06:18:45.987692 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: MajorDeltaCompactionOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.188s	user 0.107s	sys 0.069s 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":567,"lbm_read_time_us":13236,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32438,"lbm_writes_lt_1ms":543,"mutex_wait_us":58,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:45.988481 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=14.095187
I20260812 06:18:46.046900 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.058s	user 0.026s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19750,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:46.047619 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=2.188937
I20260812 06:18:46.058508 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4291,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.058943 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling MajorDeltaCompactionOp(24cb268947644fd2a4d176f506680e0c): perf score=1.000000
I20260812 06:18:46.245620 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: MajorDeltaCompactionOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.187s	user 0.137s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":439,"lbm_read_time_us":12307,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30532,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2500}
I20260812 06:18:46.246340 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=14.095187
I20260812 06:18:46.297508 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.051s	user 0.034s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19038,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:46.298105 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=2.188937
I20260812 06:18:46.317811 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.020s	user 0.003s	sys 0.014s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4942,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.318388 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling MajorDeltaCompactionOp(24cb268947644fd2a4d176f506680e0c): perf score=1.000000
I20260812 06:18:46.503001 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: MajorDeltaCompactionOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.184s	user 0.125s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":517,"lbm_read_time_us":13355,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29883,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2500}
I20260812 06:18:46.503571 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=14.095187
I20260812 06:18:46.560925 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.057s	user 0.040s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24407,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:46.561427 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=2.188937
I20260812 06:18:46.572638 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4163,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.573180 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling MajorDeltaCompactionOp(24cb268947644fd2a4d176f506680e0c): perf score=1.000000
I20260812 06:18:46.759783 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: MajorDeltaCompactionOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.186s	user 0.137s	sys 0.037s 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":650,"lbm_read_time_us":12943,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29737,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18688,"update_count":2500}
I20260812 06:18:46.760324 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=14.095187
I20260812 06:18:46.816959 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.056s	user 0.030s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":27725,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:46.817487 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=2.188937
I20260812 06:18:46.829950 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4749,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.830488 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushMRSOp(24cb268947644fd2a4d176f506680e0c): perf score=1.000000
I20260812 06:18:46.863322 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushMRSOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.033s	user 0.027s	sys 0.004s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":76,"dirs.run_cpu_time_us":282,"dirs.run_wall_time_us":1152,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1548,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:46.864858 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling LogGCOp(24cb268947644fd2a4d176f506680e0c): free 133024698 bytes of WAL
I20260812 06:18:46.865136 20565 log_reader.cc:385] T 24cb268947644fd2a4d176f506680e0c: removed 13 log segments from log reader
I20260812 06:18:46.865202 20565 log.cc:1079] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/24cb268947644fd2a4d176f506680e0c/wal-000000027 (ops 130-134)
I20260812 06:18:46.865257 20565 log.cc:1079] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/24cb268947644fd2a4d176f506680e0c/wal-000000028 (ops 135-139)
I20260812 06:18:46.865381 20565 log.cc:1079] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/24cb268947644fd2a4d176f506680e0c/wal-000000029 (ops 140-144)
I20260812 06:18:46.865486 20565 log.cc:1079] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/24cb268947644fd2a4d176f506680e0c/wal-000000030 (ops 145-148)
I20260812 06:18:46.865578 20565 log.cc:1079] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/24cb268947644fd2a4d176f506680e0c/wal-000000031 (ops 149-153)
I20260812 06:18:46.865641 20565 log.cc:1079] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/24cb268947644fd2a4d176f506680e0c/wal-000000032 (ops 154-158)
I20260812 06:18:46.865698 20565 log.cc:1079] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/24cb268947644fd2a4d176f506680e0c/wal-000000033 (ops 159-163)
I20260812 06:18:46.865731 20565 log.cc:1079] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/24cb268947644fd2a4d176f506680e0c/wal-000000034 (ops 164-168)
I20260812 06:18:46.865813 20565 log.cc:1079] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/24cb268947644fd2a4d176f506680e0c/wal-000000035 (ops 169-173)
I20260812 06:18:46.865867 20565 log.cc:1079] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/24cb268947644fd2a4d176f506680e0c/wal-000000036 (ops 174-178)
I20260812 06:18:46.865901 20565 log.cc:1079] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/24cb268947644fd2a4d176f506680e0c/wal-000000037 (ops 179-183)
I20260812 06:18:46.865934 20565 log.cc:1079] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/24cb268947644fd2a4d176f506680e0c/wal-000000038 (ops 184-188)
I20260812 06:18:46.866015 20565 log.cc:1079] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/24cb268947644fd2a4d176f506680e0c/wal-000000039 (ops 189-193)
I20260812 06:18:46.895880 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: LogGCOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.031s	user 0.002s	sys 0.028s Metrics: {}
I20260812 06:18:46.896411 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling UndoDeltaBlockGCOp(24cb268947644fd2a4d176f506680e0c): 492 bytes on disk
I20260812 06:18:46.896870 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: UndoDeltaBlockGCOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:18:46.897540 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=6.157687
I20260812 06:18:46.919821 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.022s	user 0.010s	sys 0.012s Metrics: {"bytes_written":7917911,"delete_count":0,"lbm_write_time_us":9839,"lbm_writes_lt_1ms":196,"reinsert_count":0,"update_count":965}
I20260812 06:18:46.920341 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling MajorDeltaCompactionOp(24cb268947644fd2a4d176f506680e0c): perf score=1.000000
I20260812 06:18:47.014703 20395 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.911s	user 1.837s	sys 0.114s
I20260812 06:18:47.119043 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: MajorDeltaCompactionOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.199s	user 0.150s	sys 0.048s Metrics: {"cfile_cache_miss":726,"cfile_cache_miss_bytes":32692464,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":940,"lbm_read_time_us":15367,"lbm_reads_lt_1ms":758,"lbm_write_time_us":33508,"lbm_writes_lt_1ms":736,"mutex_wait_us":281,"peak_mem_usage":86641415,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":77,"threads_started":1,"update_count":3465}
I20260812 06:18:47.119805 20666 maintenance_manager.cc:419] P 1c4e8b6f09664ee381cd232317f44f58: Scheduling FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c): perf score=7.149875
I20260812 06:18:47.121730 20395 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.106s	user 0.003s	sys 0.000s
I20260812 06:18:47.122417 20395 tablet_server.cc:179] TabletServer@127.19.234.193:0 shutting down...
I20260812 06:18:47.170996 20565 maintenance_manager.cc:643] P 1c4e8b6f09664ee381cd232317f44f58: FlushDeltaMemStoresOp(24cb268947644fd2a4d176f506680e0c) complete. Timing: real 0.051s	user 0.014s	sys 0.007s Metrics: {"bytes_written":8492254,"delete_count":0,"lbm_write_time_us":10715,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":209,"reinsert_count":0,"update_count":1035}
I20260812 06:18:47.171891 20395 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:47.172335 20395 tablet_replica.cc:333] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58: stopping tablet replica
I20260812 06:18:47.172580 20395 raft_consensus.cc:2243] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:47.172827 20395 raft_consensus.cc:2272] T 24cb268947644fd2a4d176f506680e0c P 1c4e8b6f09664ee381cd232317f44f58 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:47.187870 20395 tablet_server.cc:196] TabletServer@127.19.234.193:0 shutdown complete.
I20260812 06:18:47.192544 20395 master.cc:562] Master@127.19.234.254:44631 shutting down...
I20260812 06:18:47.196497 20395 raft_consensus.cc:2243] T 00000000000000000000000000000000 P af0959f893d04287af9002b9a1d9ca42 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:47.196689 20395 raft_consensus.cc:2272] T 00000000000000000000000000000000 P af0959f893d04287af9002b9a1d9ca42 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:47.196785 20395 tablet_replica.cc:333] T 00000000000000000000000000000000 P af0959f893d04287af9002b9a1d9ca42: stopping tablet replica
I20260812 06:18:47.209154 20395 master.cc:584] Master@127.19.234.254:44631 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5489 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:47.308984 20395 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.19.234.254:44525
I20260812 06:18:47.309377 20395 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:47.311510 20721 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:47.311563 20719 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:47.311585 20723 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:47.311659 20395 server_base.cc:1061] running on GCE node
I20260812 06:18:47.311910 20395 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:47.311949 20395 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:47.311964 20395 hybrid_clock.cc:648] HybridClock initialized: now 1786515527311964 us; error 0 us; skew 500 ppm
I20260812 06:18:47.312763 20395 webserver.cc:533] Webserver started at http://127.19.234.254:36195/ using document root <none> and password file <none>
I20260812 06:18:47.312896 20395 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:47.312942 20395 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:47.312999 20395 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:47.313373 20395 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/master-0-root/instance:
uuid: "7193451464114db18e2178f975d4be0b"
format_stamp: "Formatted at 2026-08-12 06:18:47 on dist-test-slave-c12x"
I20260812 06:18:47.314849 20395 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:47.315860 20735 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:47.316176 20395 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:47.316303 20395 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/master-0-root
uuid: "7193451464114db18e2178f975d4be0b"
format_stamp: "Formatted at 2026-08-12 06:18:47 on dist-test-slave-c12x"
I20260812 06:18:47.316427 20395 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:47.341183 20395 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:47.341710 20395 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:47.346668 20395 rpc_server.cc:307] RPC server started. Bound to: 127.19.234.254:44525
I20260812 06:18:47.347685 20821 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.19.234.254:44525 every 8 connection(s)
I20260812 06:18:47.349440 20822 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:47.354447 20822 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 7193451464114db18e2178f975d4be0b: Bootstrap starting.
I20260812 06:18:47.355197 20822 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 7193451464114db18e2178f975d4be0b: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:47.356249 20822 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 7193451464114db18e2178f975d4be0b: No bootstrap required, opened a new log
I20260812 06:18:47.356626 20822 raft_consensus.cc:359] T 00000000000000000000000000000000 P 7193451464114db18e2178f975d4be0b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7193451464114db18e2178f975d4be0b" member_type: VOTER }
I20260812 06:18:47.356710 20822 raft_consensus.cc:385] T 00000000000000000000000000000000 P 7193451464114db18e2178f975d4be0b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:47.356732 20822 raft_consensus.cc:740] T 00000000000000000000000000000000 P 7193451464114db18e2178f975d4be0b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 7193451464114db18e2178f975d4be0b, State: Initialized, Role: FOLLOWER
I20260812 06:18:47.356873 20822 consensus_queue.cc:260] T 00000000000000000000000000000000 P 7193451464114db18e2178f975d4be0b [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: "7193451464114db18e2178f975d4be0b" member_type: VOTER }
I20260812 06:18:47.356963 20822 raft_consensus.cc:399] T 00000000000000000000000000000000 P 7193451464114db18e2178f975d4be0b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:47.356988 20822 raft_consensus.cc:493] T 00000000000000000000000000000000 P 7193451464114db18e2178f975d4be0b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:47.357021 20822 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 7193451464114db18e2178f975d4be0b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:47.357667 20822 raft_consensus.cc:515] T 00000000000000000000000000000000 P 7193451464114db18e2178f975d4be0b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7193451464114db18e2178f975d4be0b" member_type: VOTER }
I20260812 06:18:47.357779 20822 leader_election.cc:304] T 00000000000000000000000000000000 P 7193451464114db18e2178f975d4be0b [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: 7193451464114db18e2178f975d4be0b; no voters: 
I20260812 06:18:47.357923 20822 leader_election.cc:290] T 00000000000000000000000000000000 P 7193451464114db18e2178f975d4be0b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:47.358058 20825 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 7193451464114db18e2178f975d4be0b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:47.358289 20825 raft_consensus.cc:697] T 00000000000000000000000000000000 P 7193451464114db18e2178f975d4be0b [term 1 LEADER]: Becoming Leader. State: Replica: 7193451464114db18e2178f975d4be0b, State: Running, Role: LEADER
I20260812 06:18:47.358397 20822 sys_catalog.cc:565] T 00000000000000000000000000000000 P 7193451464114db18e2178f975d4be0b [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:47.358474 20825 consensus_queue.cc:237] T 00000000000000000000000000000000 P 7193451464114db18e2178f975d4be0b [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: "7193451464114db18e2178f975d4be0b" member_type: VOTER }
I20260812 06:18:47.359095 20826 sys_catalog.cc:455] T 00000000000000000000000000000000 P 7193451464114db18e2178f975d4be0b [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "7193451464114db18e2178f975d4be0b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7193451464114db18e2178f975d4be0b" member_type: VOTER } }
I20260812 06:18:47.359120 20827 sys_catalog.cc:455] T 00000000000000000000000000000000 P 7193451464114db18e2178f975d4be0b [sys.catalog]: SysCatalogTable state changed. Reason: New leader 7193451464114db18e2178f975d4be0b. Latest consensus state: current_term: 1 leader_uuid: "7193451464114db18e2178f975d4be0b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7193451464114db18e2178f975d4be0b" member_type: VOTER } }
I20260812 06:18:47.359189 20826 sys_catalog.cc:458] T 00000000000000000000000000000000 P 7193451464114db18e2178f975d4be0b [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:47.359200 20827 sys_catalog.cc:458] T 00000000000000000000000000000000 P 7193451464114db18e2178f975d4be0b [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:47.359825 20831 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:47.360773 20831 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:47.360955 20395 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:47.362897 20831 catalog_manager.cc:1383] Generated new cluster ID: 3759a8dbab5e480ebbc3fef77071f8a0
I20260812 06:18:47.362969 20831 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:47.417447 20831 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:47.418112 20831 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:47.424407 20831 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 7193451464114db18e2178f975d4be0b: Generated new TSK 0
I20260812 06:18:47.424664 20831 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:47.489913 20395 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:47.492017 20850 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:47.492110 20856 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:47.492116 20852 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:47.492422 20395 server_base.cc:1061] running on GCE node
I20260812 06:18:47.492583 20395 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:47.492619 20395 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:47.492636 20395 hybrid_clock.cc:648] HybridClock initialized: now 1786515527492636 us; error 0 us; skew 500 ppm
I20260812 06:18:47.493497 20395 webserver.cc:533] Webserver started at http://127.19.234.193:46199/ using document root <none> and password file <none>
I20260812 06:18:47.493647 20395 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:47.493700 20395 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:47.493770 20395 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:47.494174 20395 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root/instance:
uuid: "12e4161f57e84def8b687837aa8e8efc"
format_stamp: "Formatted at 2026-08-12 06:18:47 on dist-test-slave-c12x"
I20260812 06:18:47.495826 20395 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:47.496893 20865 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:47.497170 20395 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:47.497237 20395 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root
uuid: "12e4161f57e84def8b687837aa8e8efc"
format_stamp: "Formatted at 2026-08-12 06:18:47 on dist-test-slave-c12x"
I20260812 06:18:47.497347 20395 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:47.520853 20395 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:47.521337 20395 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:47.521667 20395 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:47.522171 20395 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:47.522209 20395 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:47.522265 20395 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:47.522315 20395 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:47.526798 20395 rpc_server.cc:307] RPC server started. Bound to: 127.19.234.193:40435
I20260812 06:18:47.527307 20967 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.19.234.193:40435 every 8 connection(s)
I20260812 06:18:47.539630 20968 heartbeater.cc:344] Connected to a master server at 127.19.234.254:44525
I20260812 06:18:47.539752 20968 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:47.539999 20968 heartbeater.cc:507] Master 127.19.234.254:44525 requested a full tablet report, sending...
I20260812 06:18:47.540640 20764 ts_manager.cc:194] Registered new tserver with Master: 12e4161f57e84def8b687837aa8e8efc (127.19.234.193:40435)
I20260812 06:18:47.540958 20395 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013414949s
I20260812 06:18:47.541417 20764 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:52066
I20260812 06:18:47.549015 20764 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:52082:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:47.557566 20913 tablet_service.cc:1511] Processing CreateTablet for tablet 31300e22966848698e0feba55ae5f979 (DEFAULT_TABLE table=heavy-update-compaction-test [id=a85432a3aebc4f04828d54516a6f8495]), partition=
I20260812 06:18:47.557942 20913 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 31300e22966848698e0feba55ae5f979. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:47.559988 20988 tablet_bootstrap.cc:492] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Bootstrap starting.
I20260812 06:18:47.560948 20988 tablet_bootstrap.cc:654] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:47.562000 20988 tablet_bootstrap.cc:492] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: No bootstrap required, opened a new log
I20260812 06:18:47.562107 20988 ts_tablet_manager.cc:1403] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:47.562539 20988 raft_consensus.cc:359] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "12e4161f57e84def8b687837aa8e8efc" member_type: VOTER last_known_addr { host: "127.19.234.193" port: 40435 } }
I20260812 06:18:47.562649 20988 raft_consensus.cc:385] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:47.562695 20988 raft_consensus.cc:740] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 12e4161f57e84def8b687837aa8e8efc, State: Initialized, Role: FOLLOWER
I20260812 06:18:47.562837 20988 consensus_queue.cc:260] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc [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: "12e4161f57e84def8b687837aa8e8efc" member_type: VOTER last_known_addr { host: "127.19.234.193" port: 40435 } }
I20260812 06:18:47.562937 20988 raft_consensus.cc:399] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:47.562990 20988 raft_consensus.cc:493] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:47.563048 20988 raft_consensus.cc:3060] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:47.563947 20988 raft_consensus.cc:515] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "12e4161f57e84def8b687837aa8e8efc" member_type: VOTER last_known_addr { host: "127.19.234.193" port: 40435 } }
I20260812 06:18:47.564061 20988 leader_election.cc:304] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc [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: 12e4161f57e84def8b687837aa8e8efc; no voters: 
I20260812 06:18:47.564205 20988 leader_election.cc:290] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:47.564339 20993 raft_consensus.cc:2804] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:47.564584 20993 raft_consensus.cc:697] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc [term 1 LEADER]: Becoming Leader. State: Replica: 12e4161f57e84def8b687837aa8e8efc, State: Running, Role: LEADER
I20260812 06:18:47.564615 20968 heartbeater.cc:499] Master 127.19.234.254:44525 was elected leader, sending a full tablet report...
I20260812 06:18:47.564620 20988 ts_tablet_manager.cc:1434] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:47.564797 20993 consensus_queue.cc:237] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc [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: "12e4161f57e84def8b687837aa8e8efc" member_type: VOTER last_known_addr { host: "127.19.234.193" port: 40435 } }
I20260812 06:18:47.566037 20764 catalog_manager.cc:5719] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc reported cstate change: term changed from 0 to 1, leader changed from <none> to 12e4161f57e84def8b687837aa8e8efc (127.19.234.193). New cstate: current_term: 1 leader_uuid: "12e4161f57e84def8b687837aa8e8efc" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "12e4161f57e84def8b687837aa8e8efc" member_type: VOTER last_known_addr { host: "127.19.234.193" port: 40435 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:47.630056 20395 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.014s	sys 0.009s
I20260812 06:18:47.778254 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushMRSOp(31300e22966848698e0feba55ae5f979): perf score=19.054940
I20260812 06:18:47.951398 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushMRSOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.173s	user 0.136s	sys 0.032s Metrics: {"bytes_written":12307489,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":53,"dirs.run_cpu_time_us":178,"dirs.run_wall_time_us":780,"drs_written":1,"lbm_read_time_us":84,"lbm_reads_lt_1ms":4,"lbm_write_time_us":45964,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:18:47.952135 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling LogGCOp(31300e22966848698e0feba55ae5f979): free 20743880 bytes of WAL
I20260812 06:18:47.952389 20871 log_reader.cc:385] T 31300e22966848698e0feba55ae5f979: removed 2 log segments from log reader
I20260812 06:18:47.952437 20871 log.cc:1079] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/31300e22966848698e0feba55ae5f979/wal-000000001 (ops 1-6)
I20260812 06:18:47.952473 20871 log.cc:1079] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/31300e22966848698e0feba55ae5f979/wal-000000002 (ops 7-11)
I20260812 06:18:47.956972 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: LogGCOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:47.957361 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=2.188937
I20260812 06:18:47.972913 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.015s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6136,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.973317 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling UndoDeltaBlockGCOp(31300e22966848698e0feba55ae5f979): 16411393 bytes on disk
I20260812 06:18:47.973680 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: UndoDeltaBlockGCOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:18:47.974058 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling MajorDeltaCompactionOp(31300e22966848698e0feba55ae5f979): perf score=1.000000
I20260812 06:18:48.130532 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: MajorDeltaCompactionOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.156s	user 0.110s	sys 0.045s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":424,"lbm_read_time_us":10951,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27518,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":287,"threads_started":5,"update_count":2000}
I20260812 06:18:48.131076 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=10.126437
I20260812 06:18:48.174960 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.044s	user 0.017s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14518,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:48.175726 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=2.188937
I20260812 06:18:48.198307 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.022s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6720,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.198771 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=2.188937
I20260812 06:18:48.208942 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4051,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.209335 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling MajorDeltaCompactionOp(31300e22966848698e0feba55ae5f979): perf score=1.000000
I20260812 06:18:48.381664 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: MajorDeltaCompactionOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.172s	user 0.103s	sys 0.064s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774808,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":150,"lbm_read_time_us":11699,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29112,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:18:48.382400 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=14.095187
I20260812 06:18:48.445400 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.063s	user 0.023s	sys 0.037s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":23111,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:48.445925 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=2.188937
I20260812 06:18:48.457366 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4493,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.457841 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling MajorDeltaCompactionOp(31300e22966848698e0feba55ae5f979): perf score=1.000000
I20260812 06:18:48.649534 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: MajorDeltaCompactionOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.192s	user 0.118s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1564,"lbm_read_time_us":13701,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31525,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:48.650084 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=14.095187
I20260812 06:18:48.712522 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.062s	user 0.024s	sys 0.028s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18875,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:48.713129 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=2.188937
I20260812 06:18:48.725056 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.012s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4522,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.725515 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling MajorDeltaCompactionOp(31300e22966848698e0feba55ae5f979): perf score=1.000000
I20260812 06:18:48.919023 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: MajorDeltaCompactionOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.193s	user 0.121s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":213,"lbm_read_time_us":12913,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30260,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2500}
I20260812 06:18:48.919737 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=11.118625
I20260812 06:18:48.970644 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.051s	user 0.017s	sys 0.024s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16921,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:48.971122 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=2.188937
I20260812 06:18:48.983263 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4100,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.983753 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=2.188937
I20260812 06:18:48.993033 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3431,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:48.993542 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling MajorDeltaCompactionOp(31300e22966848698e0feba55ae5f979): perf score=1.000000
I20260812 06:18:49.194550 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: MajorDeltaCompactionOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.201s	user 0.142s	sys 0.047s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":326,"lbm_read_time_us":13454,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31133,"lbm_writes_lt_1ms":543,"mutex_wait_us":76,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":2500}
I20260812 06:18:49.195386 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=14.095187
I20260812 06:18:49.249678 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.054s	user 0.027s	sys 0.025s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23023,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:49.250267 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=2.188937
I20260812 06:18:49.264550 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.014s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5047,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.265136 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushMRSOp(31300e22966848698e0feba55ae5f979): perf score=1.000000
I20260812 06:18:49.296244 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushMRSOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.031s	user 0.029s	sys 0.001s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":227,"dirs.run_wall_time_us":1161,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1983,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:49.296845 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling LogGCOp(31300e22966848698e0feba55ae5f979): free 115943173 bytes of WAL
I20260812 06:18:49.297080 20871 log_reader.cc:385] T 31300e22966848698e0feba55ae5f979: removed 11 log segments from log reader
I20260812 06:18:49.297120 20871 log.cc:1079] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/31300e22966848698e0feba55ae5f979/wal-000000003 (ops 12-16)
I20260812 06:18:49.297149 20871 log.cc:1079] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/31300e22966848698e0feba55ae5f979/wal-000000004 (ops 17-21)
I20260812 06:18:49.297166 20871 log.cc:1079] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/31300e22966848698e0feba55ae5f979/wal-000000005 (ops 22-26)
I20260812 06:18:49.297231 20871 log.cc:1079] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/31300e22966848698e0feba55ae5f979/wal-000000006 (ops 27-31)
I20260812 06:18:49.297268 20871 log.cc:1079] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/31300e22966848698e0feba55ae5f979/wal-000000007 (ops 32-36)
I20260812 06:18:49.297297 20871 log.cc:1079] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/31300e22966848698e0feba55ae5f979/wal-000000008 (ops 37-41)
I20260812 06:18:49.297336 20871 log.cc:1079] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/31300e22966848698e0feba55ae5f979/wal-000000009 (ops 42-46)
I20260812 06:18:49.297448 20871 log.cc:1079] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/31300e22966848698e0feba55ae5f979/wal-000000010 (ops 47-51)
I20260812 06:18:49.297489 20871 log.cc:1079] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/31300e22966848698e0feba55ae5f979/wal-000000011 (ops 52-56)
I20260812 06:18:49.297533 20871 log.cc:1079] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/31300e22966848698e0feba55ae5f979/wal-000000012 (ops 57-61)
I20260812 06:18:49.297576 20871 log.cc:1079] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/31300e22966848698e0feba55ae5f979/wal-000000013 (ops 62-66)
I20260812 06:18:49.326380 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: LogGCOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.029s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:49.327127 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=4.173312
I20260812 06:18:49.340549 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":5333393,"delete_count":0,"lbm_write_time_us":5437,"lbm_writes_lt_1ms":133,"reinsert_count":0,"update_count":650}
I20260812 06:18:49.340987 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=1.196750
I20260812 06:18:49.349308 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.008s	user 0.004s	sys 0.003s Metrics: {"bytes_written":2871905,"delete_count":0,"lbm_write_time_us":3095,"lbm_writes_lt_1ms":73,"reinsert_count":0,"update_count":350}
I20260812 06:18:49.349697 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling MajorDeltaCompactionOp(31300e22966848698e0feba55ae5f979): perf score=1.000000
I20260812 06:18:49.604775 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: MajorDeltaCompactionOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.255s	user 0.191s	sys 0.063s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979726,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":800,"lbm_read_time_us":17186,"lbm_reads_lt_1ms":774,"lbm_write_time_us":43751,"lbm_writes_lt_1ms":743,"mutex_wait_us":107,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":23040,"thread_start_us":81,"threads_started":1,"update_count":3500}
I20260812 06:18:49.607838 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=15.087375
I20260812 06:18:49.672294 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.061s	user 0.031s	sys 0.026s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":25194,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:49.673069 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling UndoDeltaBlockGCOp(31300e22966848698e0feba55ae5f979): 463 bytes on disk
I20260812 06:18:49.673657 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: UndoDeltaBlockGCOp(31300e22966848698e0feba55ae5f979) 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:18:49.674293 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=2.188937
I20260812 06:18:49.692544 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.018s	user 0.012s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5104,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:49.693084 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling MajorDeltaCompactionOp(31300e22966848698e0feba55ae5f979): perf score=1.000000
I20260812 06:18:49.860716 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: MajorDeltaCompactionOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.167s	user 0.117s	sys 0.049s 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":428,"lbm_read_time_us":11088,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29662,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2500}
I20260812 06:18:49.861385 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=14.095187
I20260812 06:18:49.909976 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.048s	user 0.028s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22173,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:49.910564 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=2.188937
I20260812 06:18:49.923677 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.013s	user 0.002s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4958,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.924229 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling MajorDeltaCompactionOp(31300e22966848698e0feba55ae5f979): perf score=1.000000
I20260812 06:18:50.107589 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: MajorDeltaCompactionOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.183s	user 0.124s	sys 0.048s 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":772,"lbm_read_time_us":11489,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29194,"lbm_writes_lt_1ms":543,"mutex_wait_us":131,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16640,"update_count":2500}
I20260812 06:18:50.108804 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=14.095187
I20260812 06:18:50.165185 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.056s	user 0.035s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19636,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:50.165870 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=2.188937
I20260812 06:18:50.177141 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4335,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.177623 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling MajorDeltaCompactionOp(31300e22966848698e0feba55ae5f979): perf score=1.000000
I20260812 06:18:50.360858 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: MajorDeltaCompactionOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.183s	user 0.112s	sys 0.060s 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":418,"lbm_read_time_us":12456,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28998,"lbm_writes_lt_1ms":543,"mutex_wait_us":107,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2500}
I20260812 06:18:50.361601 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=14.095187
I20260812 06:18:50.413209 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.051s	user 0.035s	sys 0.008s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":20265,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:50.413724 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=2.188937
I20260812 06:18:50.437139 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.023s	user 0.010s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4756,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.437798 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling MajorDeltaCompactionOp(31300e22966848698e0feba55ae5f979): perf score=1.000000
I20260812 06:18:50.614468 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: MajorDeltaCompactionOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.176s	user 0.117s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774692,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1408,"lbm_read_time_us":12511,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28271,"lbm_writes_lt_1ms":543,"mutex_wait_us":338,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7552,"update_count":2500}
I20260812 06:18:50.615191 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=14.095187
I20260812 06:18:50.664532 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.049s	user 0.020s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21679,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:50.665177 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=2.188937
I20260812 06:18:50.683706 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.018s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6651,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.684187 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushMRSOp(31300e22966848698e0feba55ae5f979): perf score=1.000000
I20260812 06:18:50.714054 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushMRSOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.030s	user 0.022s	sys 0.004s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":38,"dirs.run_cpu_time_us":249,"dirs.run_wall_time_us":1345,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2091,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:50.714676 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling LogGCOp(31300e22966848698e0feba55ae5f979): free 108535407 bytes of WAL
I20260812 06:18:50.714905 20871 log_reader.cc:385] T 31300e22966848698e0feba55ae5f979: removed 11 log segments from log reader
I20260812 06:18:50.714948 20871 log.cc:1079] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/31300e22966848698e0feba55ae5f979/wal-000000014 (ops 67-71)
I20260812 06:18:50.714977 20871 log.cc:1079] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/31300e22966848698e0feba55ae5f979/wal-000000015 (ops 72-76)
I20260812 06:18:50.715042 20871 log.cc:1079] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/31300e22966848698e0feba55ae5f979/wal-000000016 (ops 77-81)
I20260812 06:18:50.715077 20871 log.cc:1079] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/31300e22966848698e0feba55ae5f979/wal-000000017 (ops 82-86)
I20260812 06:18:50.715119 20871 log.cc:1079] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/31300e22966848698e0feba55ae5f979/wal-000000018 (ops 87-90)
I20260812 06:18:50.715138 20871 log.cc:1079] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/31300e22966848698e0feba55ae5f979/wal-000000019 (ops 91-95)
I20260812 06:18:50.715197 20871 log.cc:1079] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/31300e22966848698e0feba55ae5f979/wal-000000020 (ops 96-100)
I20260812 06:18:50.715235 20871 log.cc:1079] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/31300e22966848698e0feba55ae5f979/wal-000000021 (ops 101-105)
I20260812 06:18:50.715274 20871 log.cc:1079] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/31300e22966848698e0feba55ae5f979/wal-000000022 (ops 106-110)
I20260812 06:18:50.715312 20871 log.cc:1079] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/31300e22966848698e0feba55ae5f979/wal-000000023 (ops 111-114)
I20260812 06:18:50.715350 20871 log.cc:1079] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/31300e22966848698e0feba55ae5f979/wal-000000024 (ops 115-119)
I20260812 06:18:50.741453 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: LogGCOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.027s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:50.741979 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=3.181125
I20260812 06:18:50.773227 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.031s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6626,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:50.773697 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling LogGCOp(31300e22966848698e0feba55ae5f979): free 8767172 bytes of WAL
I20260812 06:18:50.773901 20871 log_reader.cc:385] T 31300e22966848698e0feba55ae5f979: removed 1 log segments from log reader
I20260812 06:18:50.773944 20871 log.cc:1079] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/31300e22966848698e0feba55ae5f979/wal-000000025 (ops 120-124)
I20260812 06:18:50.775676 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: LogGCOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.002s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:50.775985 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling UndoDeltaBlockGCOp(31300e22966848698e0feba55ae5f979): 447 bytes on disk
I20260812 06:18:50.776386 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: UndoDeltaBlockGCOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:18:50.776854 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=2.188937
I20260812 06:18:50.786674 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3678,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:50.787571 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling MajorDeltaCompactionOp(31300e22966848698e0feba55ae5f979): perf score=1.000000
I20260812 06:18:51.047987 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: MajorDeltaCompactionOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.260s	user 0.168s	sys 0.086s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979740,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":805,"lbm_read_time_us":16642,"lbm_reads_lt_1ms":774,"lbm_write_time_us":44324,"lbm_writes_lt_1ms":743,"mutex_wait_us":426,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":17280,"thread_start_us":80,"threads_started":1,"update_count":3500}
I20260812 06:18:51.048609 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=18.063937
I20260812 06:18:51.125384 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.077s	user 0.022s	sys 0.041s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":29823,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:51.125921 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=2.188937
I20260812 06:18:51.142580 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6024,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:51.143270 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling MajorDeltaCompactionOp(31300e22966848698e0feba55ae5f979): perf score=1.000000
I20260812 06:18:51.351405 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: MajorDeltaCompactionOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.208s	user 0.123s	sys 0.081s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":345,"lbm_read_time_us":13776,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34504,"lbm_writes_lt_1ms":643,"mutex_wait_us":28,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":3000}
I20260812 06:18:51.352151 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=15.087375
I20260812 06:18:51.403801 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.051s	user 0.027s	sys 0.023s Metrics: {"bytes_written":16820144,"delete_count":0,"lbm_write_time_us":22728,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:51.404383 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=2.188937
I20260812 06:18:51.420379 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.016s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3897534,"delete_count":0,"lbm_write_time_us":5712,"lbm_writes_lt_1ms":98,"reinsert_count":0,"update_count":475}
I20260812 06:18:51.421192 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling MajorDeltaCompactionOp(31300e22966848698e0feba55ae5f979): perf score=1.000000
I20260812 06:18:51.613118 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: MajorDeltaCompactionOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.192s	user 0.122s	sys 0.069s Metrics: {"cfile_cache_miss":537,"cfile_cache_miss_bytes":24979806,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":226,"lbm_read_time_us":13987,"lbm_reads_lt_1ms":569,"lbm_write_time_us":33963,"lbm_writes_lt_1ms":548,"mutex_wait_us":26,"peak_mem_usage":63321075,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2525}
I20260812 06:18:51.613852 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=14.095187
I20260812 06:18:51.685672 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.072s	user 0.029s	sys 0.035s Metrics: {"bytes_written":16204784,"delete_count":0,"lbm_write_time_us":31527,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":397,"reinsert_count":0,"update_count":1975}
I20260812 06:18:51.686246 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=2.188937
I20260812 06:18:51.701043 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5045,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:51.701628 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling MajorDeltaCompactionOp(31300e22966848698e0feba55ae5f979): perf score=1.000000
I20260812 06:18:51.886955 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: MajorDeltaCompactionOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.185s	user 0.130s	sys 0.052s Metrics: {"cfile_cache_miss":527,"cfile_cache_miss_bytes":24569571,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":445,"lbm_read_time_us":13023,"lbm_reads_lt_1ms":559,"lbm_write_time_us":32444,"lbm_writes_lt_1ms":538,"peak_mem_usage":61870341,"reinsert_count":0,"spinlock_wait_cycles":5120,"update_count":2475}
I20260812 06:18:51.887822 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=14.095187
I20260812 06:18:51.956538 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.068s	user 0.036s	sys 0.024s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":23305,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:51.957118 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=2.188937
I20260812 06:18:51.968225 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4404,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:51.968751 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling MajorDeltaCompactionOp(31300e22966848698e0feba55ae5f979): perf score=1.000000
I20260812 06:18:52.143170 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: MajorDeltaCompactionOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.174s	user 0.108s	sys 0.066s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":275,"lbm_read_time_us":12548,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29177,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15488,"update_count":2500}
I20260812 06:18:52.144287 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=10.126437
I20260812 06:18:52.189589 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.045s	user 0.018s	sys 0.022s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18663,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:52.190186 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=2.188937
I20260812 06:18:52.202296 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4568,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:52.202811 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling MajorDeltaCompactionOp(31300e22966848698e0feba55ae5f979): perf score=1.000000
I20260812 06:18:52.331498 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: MajorDeltaCompactionOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.128s	user 0.108s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":980,"lbm_read_time_us":10067,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24158,"lbm_writes_lt_1ms":443,"mutex_wait_us":275,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2000}
I20260812 06:18:52.332325 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=10.126437
I20260812 06:18:52.380985 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.048s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":18034,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:52.381529 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=2.188937
I20260812 06:18:52.392376 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.011s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4197,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:52.393362 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushMRSOp(31300e22966848698e0feba55ae5f979): perf score=1.000000
I20260812 06:18:52.425112 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushMRSOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.031s	user 0.021s	sys 0.006s Metrics: {"bytes_written":1234475,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":273,"dirs.run_wall_time_us":1538,"drs_written":1,"lbm_read_time_us":82,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1490,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30,"spinlock_wait_cycles":4992}
I20260812 06:18:52.425910 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling LogGCOp(31300e22966848698e0feba55ae5f979): free 120100567 bytes of WAL
I20260812 06:18:52.426146 20871 log_reader.cc:385] T 31300e22966848698e0feba55ae5f979: removed 12 log segments from log reader
I20260812 06:18:52.426190 20871 log.cc:1079] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/31300e22966848698e0feba55ae5f979/wal-000000026 (ops 125-128)
I20260812 06:18:52.426220 20871 log.cc:1079] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/31300e22966848698e0feba55ae5f979/wal-000000027 (ops 129-133)
I20260812 06:18:52.426282 20871 log.cc:1079] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/31300e22966848698e0feba55ae5f979/wal-000000028 (ops 134-138)
I20260812 06:18:52.426323 20871 log.cc:1079] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/31300e22966848698e0feba55ae5f979/wal-000000029 (ops 139-142)
I20260812 06:18:52.426402 20871 log.cc:1079] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/31300e22966848698e0feba55ae5f979/wal-000000030 (ops 143-147)
I20260812 06:18:52.426460 20871 log.cc:1079] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/31300e22966848698e0feba55ae5f979/wal-000000031 (ops 148-152)
I20260812 06:18:52.426503 20871 log.cc:1079] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/31300e22966848698e0feba55ae5f979/wal-000000032 (ops 153-156)
I20260812 06:18:52.426542 20871 log.cc:1079] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/31300e22966848698e0feba55ae5f979/wal-000000033 (ops 157-161)
I20260812 06:18:52.426581 20871 log.cc:1079] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/31300e22966848698e0feba55ae5f979/wal-000000034 (ops 162-166)
I20260812 06:18:52.426620 20871 log.cc:1079] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/31300e22966848698e0feba55ae5f979/wal-000000035 (ops 167-171)
I20260812 06:18:52.426658 20871 log.cc:1079] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/31300e22966848698e0feba55ae5f979/wal-000000036 (ops 172-176)
I20260812 06:18:52.426697 20871 log.cc:1079] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/31300e22966848698e0feba55ae5f979/wal-000000037 (ops 177-181)
I20260812 06:18:52.453902 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: LogGCOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:52.454388 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling UndoDeltaBlockGCOp(31300e22966848698e0feba55ae5f979): 473 bytes on disk
I20260812 06:18:52.455055 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: UndoDeltaBlockGCOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:18:52.455828 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=3.181125
I20260812 06:18:52.471753 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.016s	user 0.012s	sys 0.001s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":5186,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:52.472252 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling LogGCOp(31300e22966848698e0feba55ae5f979): free 12017954 bytes of WAL
I20260812 06:18:52.472640 20871 log_reader.cc:385] T 31300e22966848698e0feba55ae5f979: removed 1 log segments from log reader
I20260812 06:18:52.472713 20871 log.cc:1079] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: Deleting log segment in path: /tmp/dist-test-taskYsEhhi/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515521798750-20395-0/minicluster-data/ts-0-root/wals/31300e22966848698e0feba55ae5f979/wal-000000038 (ops 182-186)
I20260812 06:18:52.474977 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: LogGCOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:52.475323 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=2.188937
I20260812 06:18:52.486598 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3743,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:52.487116 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling MajorDeltaCompactionOp(31300e22966848698e0feba55ae5f979): perf score=1.000000
I20260812 06:18:52.661828 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: MajorDeltaCompactionOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.174s	user 0.130s	sys 0.044s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877330,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":530,"lbm_read_time_us":12430,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34257,"lbm_writes_lt_1ms":643,"mutex_wait_us":22,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4352,"thread_start_us":73,"threads_started":1,"update_count":3000}
I20260812 06:18:52.662875 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=14.095187
I20260812 06:18:52.713902 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.051s	user 0.037s	sys 0.007s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19998,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:52.714418 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=2.188937
I20260812 06:18:52.728262 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.014s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5381,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:52.728857 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling MajorDeltaCompactionOp(31300e22966848698e0feba55ae5f979): perf score=1.000000
I20260812 06:18:52.806658 20395 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.177s	user 1.862s	sys 0.215s
I20260812 06:18:52.865020 20395 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.058s	user 0.001s	sys 0.000s
I20260812 06:18:52.865514 20395 tablet_server.cc:179] TabletServer@127.19.234.193:0 shutting down...
I20260812 06:18:52.868338 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: MajorDeltaCompactionOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.139s	user 0.121s	sys 0.017s 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":241,"lbm_read_time_us":11121,"lbm_reads_lt_1ms":568,"lbm_write_time_us":28471,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2500}
I20260812 06:18:52.869093 20971 maintenance_manager.cc:419] P 12e4161f57e84def8b687837aa8e8efc: Scheduling FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979): perf score=6.157687
I20260812 06:18:52.889971 20871 maintenance_manager.cc:643] P 12e4161f57e84def8b687837aa8e8efc: FlushDeltaMemStoresOp(31300e22966848698e0feba55ae5f979) complete. Timing: real 0.021s	user 0.011s	sys 0.007s Metrics: {"bytes_written":8205077,"delete_count":0,"lbm_write_time_us":8749,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:52.890532 20395 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:52.891559 20395 tablet_replica.cc:333] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc: stopping tablet replica
I20260812 06:18:52.891709 20395 raft_consensus.cc:2243] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:52.891846 20395 raft_consensus.cc:2272] T 31300e22966848698e0feba55ae5f979 P 12e4161f57e84def8b687837aa8e8efc [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:52.895722 20395 tablet_server.cc:196] TabletServer@127.19.234.193:0 shutdown complete.
I20260812 06:18:52.914491 20395 master.cc:562] Master@127.19.234.254:44525 shutting down...
I20260812 06:18:52.918421 20395 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 7193451464114db18e2178f975d4be0b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:52.918599 20395 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 7193451464114db18e2178f975d4be0b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:52.918700 20395 tablet_replica.cc:333] T 00000000000000000000000000000000 P 7193451464114db18e2178f975d4be0b: stopping tablet replica
I20260812 06:18:52.931113 20395 master.cc:584] Master@127.19.234.254:44525 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5721 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11211 ms total)

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