[==========] 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:19:21.755692 23147 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.22.154.254:35941
I20260812 06:19:21.756911 23147 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:19:21.757582 23147 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:21.764384 23155 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:19:21.764843 23156 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:19:21.764912 23158 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:19:21.765360 23147 server_base.cc:1061] running on GCE node
I20260812 06:19:21.765900 23147 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:21.766150 23147 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:19:21.766219 23147 hybrid_clock.cc:648] HybridClock initialized: now 1786515561766217 us; error 0 us; skew 500 ppm
I20260812 06:19:21.771958 23147 webserver.cc:533] Webserver started at http://127.22.154.254:35977/ using document root <none> and password file <none>
I20260812 06:19:21.772650 23147 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:21.772725 23147 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:21.772940 23147 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:21.774765 23147 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/master-0-root/instance:
uuid: "410df3f933eb4403996058f674ae6cc3"
format_stamp: "Formatted at 2026-08-12 06:19:21 on dist-test-slave-rnrw"
I20260812 06:19:21.778658 23147 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:19:21.781041 23164 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:19:21.782279 23147 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:21.782397 23147 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/master-0-root
uuid: "410df3f933eb4403996058f674ae6cc3"
format_stamp: "Formatted at 2026-08-12 06:19:21 on dist-test-slave-rnrw"
I20260812 06:19:21.782500 23147 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-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:19:21.798266 23147 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:21.798991 23147 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:19:21.799156 23147 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:21.807727 23147 rpc_server.cc:307] RPC server started. Bound to: 127.22.154.254:35941
I20260812 06:19:21.807749 23226 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.22.154.254:35941 every 8 connection(s)
I20260812 06:19:21.810293 23228 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:19:21.816231 23228 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 410df3f933eb4403996058f674ae6cc3: Bootstrap starting.
I20260812 06:19:21.819151 23228 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 410df3f933eb4403996058f674ae6cc3: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:21.820242 23228 log.cc:826] T 00000000000000000000000000000000 P 410df3f933eb4403996058f674ae6cc3: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:21.822254 23228 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 410df3f933eb4403996058f674ae6cc3: No bootstrap required, opened a new log
I20260812 06:19:21.826120 23228 raft_consensus.cc:359] T 00000000000000000000000000000000 P 410df3f933eb4403996058f674ae6cc3 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "410df3f933eb4403996058f674ae6cc3" member_type: VOTER }
I20260812 06:19:21.826370 23228 raft_consensus.cc:385] T 00000000000000000000000000000000 P 410df3f933eb4403996058f674ae6cc3 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:21.826493 23228 raft_consensus.cc:740] T 00000000000000000000000000000000 P 410df3f933eb4403996058f674ae6cc3 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 410df3f933eb4403996058f674ae6cc3, State: Initialized, Role: FOLLOWER
I20260812 06:19:21.827364 23228 consensus_queue.cc:260] T 00000000000000000000000000000000 P 410df3f933eb4403996058f674ae6cc3 [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: "410df3f933eb4403996058f674ae6cc3" member_type: VOTER }
I20260812 06:19:21.827621 23228 raft_consensus.cc:399] T 00000000000000000000000000000000 P 410df3f933eb4403996058f674ae6cc3 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:21.827713 23228 raft_consensus.cc:493] T 00000000000000000000000000000000 P 410df3f933eb4403996058f674ae6cc3 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:21.827859 23228 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 410df3f933eb4403996058f674ae6cc3 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:21.829294 23228 raft_consensus.cc:515] T 00000000000000000000000000000000 P 410df3f933eb4403996058f674ae6cc3 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "410df3f933eb4403996058f674ae6cc3" member_type: VOTER }
I20260812 06:19:21.829942 23228 leader_election.cc:304] T 00000000000000000000000000000000 P 410df3f933eb4403996058f674ae6cc3 [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: 410df3f933eb4403996058f674ae6cc3; no voters: 
I20260812 06:19:21.830433 23228 leader_election.cc:290] T 00000000000000000000000000000000 P 410df3f933eb4403996058f674ae6cc3 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:21.830715 23231 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 410df3f933eb4403996058f674ae6cc3 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:21.831010 23231 raft_consensus.cc:697] T 00000000000000000000000000000000 P 410df3f933eb4403996058f674ae6cc3 [term 1 LEADER]: Becoming Leader. State: Replica: 410df3f933eb4403996058f674ae6cc3, State: Running, Role: LEADER
I20260812 06:19:21.831521 23231 consensus_queue.cc:237] T 00000000000000000000000000000000 P 410df3f933eb4403996058f674ae6cc3 [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: "410df3f933eb4403996058f674ae6cc3" member_type: VOTER }
I20260812 06:19:21.831967 23228 sys_catalog.cc:565] T 00000000000000000000000000000000 P 410df3f933eb4403996058f674ae6cc3 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:21.833835 23232 sys_catalog.cc:455] T 00000000000000000000000000000000 P 410df3f933eb4403996058f674ae6cc3 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "410df3f933eb4403996058f674ae6cc3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "410df3f933eb4403996058f674ae6cc3" member_type: VOTER } }
I20260812 06:19:21.833992 23232 sys_catalog.cc:458] T 00000000000000000000000000000000 P 410df3f933eb4403996058f674ae6cc3 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:21.834695 23233 sys_catalog.cc:455] T 00000000000000000000000000000000 P 410df3f933eb4403996058f674ae6cc3 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 410df3f933eb4403996058f674ae6cc3. Latest consensus state: current_term: 1 leader_uuid: "410df3f933eb4403996058f674ae6cc3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "410df3f933eb4403996058f674ae6cc3" member_type: VOTER } }
I20260812 06:19:21.834751 23241 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:21.834888 23233 sys_catalog.cc:458] T 00000000000000000000000000000000 P 410df3f933eb4403996058f674ae6cc3 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:21.834838 23147 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:21.839423 23241 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:21.847111 23241 catalog_manager.cc:1383] Generated new cluster ID: 3e7fed1de114425697361cb0326a1b8f
I20260812 06:19:21.847200 23241 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:21.857939 23241 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:21.858952 23241 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:21.870137 23241 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 410df3f933eb4403996058f674ae6cc3: Generated new TSK 0
I20260812 06:19:21.871193 23241 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:21.902000 23147 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:21.905373 23254 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:19:21.905455 23253 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:19:21.905355 23256 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:19:21.905920 23147 server_base.cc:1061] running on GCE node
I20260812 06:19:21.906142 23147 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:21.906203 23147 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:19:21.906237 23147 hybrid_clock.cc:648] HybridClock initialized: now 1786515561906236 us; error 0 us; skew 500 ppm
I20260812 06:19:21.907286 23147 webserver.cc:533] Webserver started at http://127.22.154.193:36125/ using document root <none> and password file <none>
I20260812 06:19:21.907490 23147 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:21.907568 23147 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:21.907651 23147 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:21.908208 23147 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root/instance:
uuid: "56717fd1fc1d414ea8e901573279f261"
format_stamp: "Formatted at 2026-08-12 06:19:21 on dist-test-slave-rnrw"
I20260812 06:19:21.910004 23147 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:21.911149 23262 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:19:21.911418 23147 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:21.911499 23147 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root
uuid: "56717fd1fc1d414ea8e901573279f261"
format_stamp: "Formatted at 2026-08-12 06:19:21 on dist-test-slave-rnrw"
I20260812 06:19:21.911593 23147 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-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:19:21.919538 23147 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:21.920051 23147 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:21.920632 23147 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:21.921770 23147 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:21.921833 23147 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:21.921917 23147 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:21.921962 23147 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:21.929616 23147 rpc_server.cc:307] RPC server started. Bound to: 127.22.154.193:44149
I20260812 06:19:21.929643 23344 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.22.154.193:44149 every 8 connection(s)
I20260812 06:19:21.941224 23345 heartbeater.cc:344] Connected to a master server at 127.22.154.254:35941
I20260812 06:19:21.941525 23345 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:21.942108 23345 heartbeater.cc:507] Master 127.22.154.254:35941 requested a full tablet report, sending...
I20260812 06:19:21.943861 23183 ts_manager.cc:194] Registered new tserver with Master: 56717fd1fc1d414ea8e901573279f261 (127.22.154.193:44149)
I20260812 06:19:21.943926 23147 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013566834s
I20260812 06:19:21.945484 23183 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:38948
I20260812 06:19:21.955356 23183 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:38958:
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:19:21.972365 23298 tablet_service.cc:1511] Processing CreateTablet for tablet acfc8bb6b7364047a652d46a5122973e (DEFAULT_TABLE table=heavy-update-compaction-test [id=594a5a768fd14a66a93d2c660822d1f8]), partition=
I20260812 06:19:21.972909 23298 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet acfc8bb6b7364047a652d46a5122973e. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:21.975606 23361 tablet_bootstrap.cc:492] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Bootstrap starting.
I20260812 06:19:21.976658 23361 tablet_bootstrap.cc:654] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:21.977952 23361 tablet_bootstrap.cc:492] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: No bootstrap required, opened a new log
I20260812 06:19:21.978081 23361 ts_tablet_manager.cc:1403] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Time spent bootstrapping tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:19:21.978609 23361 raft_consensus.cc:359] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "56717fd1fc1d414ea8e901573279f261" member_type: VOTER last_known_addr { host: "127.22.154.193" port: 44149 } }
I20260812 06:19:21.978736 23361 raft_consensus.cc:385] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:21.978770 23361 raft_consensus.cc:740] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 56717fd1fc1d414ea8e901573279f261, State: Initialized, Role: FOLLOWER
I20260812 06:19:21.978912 23361 consensus_queue.cc:260] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261 [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: "56717fd1fc1d414ea8e901573279f261" member_type: VOTER last_known_addr { host: "127.22.154.193" port: 44149 } }
I20260812 06:19:21.979001 23361 raft_consensus.cc:399] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:21.979097 23361 raft_consensus.cc:493] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:21.979156 23361 raft_consensus.cc:3060] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:21.980223 23361 raft_consensus.cc:515] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "56717fd1fc1d414ea8e901573279f261" member_type: VOTER last_known_addr { host: "127.22.154.193" port: 44149 } }
I20260812 06:19:21.980384 23361 leader_election.cc:304] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261 [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: 56717fd1fc1d414ea8e901573279f261; no voters: 
I20260812 06:19:21.980659 23361 leader_election.cc:290] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:21.980803 23363 raft_consensus.cc:2804] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:21.981038 23361 ts_tablet_manager.cc:1434] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:19:21.981213 23363 raft_consensus.cc:697] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261 [term 1 LEADER]: Becoming Leader. State: Replica: 56717fd1fc1d414ea8e901573279f261, State: Running, Role: LEADER
I20260812 06:19:21.981475 23345 heartbeater.cc:499] Master 127.22.154.254:35941 was elected leader, sending a full tablet report...
I20260812 06:19:21.981468 23363 consensus_queue.cc:237] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261 [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: "56717fd1fc1d414ea8e901573279f261" member_type: VOTER last_known_addr { host: "127.22.154.193" port: 44149 } }
I20260812 06:19:21.984839 23183 catalog_manager.cc:5719] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261 reported cstate change: term changed from 0 to 1, leader changed from <none> to 56717fd1fc1d414ea8e901573279f261 (127.22.154.193). New cstate: current_term: 1 leader_uuid: "56717fd1fc1d414ea8e901573279f261" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "56717fd1fc1d414ea8e901573279f261" member_type: VOTER last_known_addr { host: "127.22.154.193" port: 44149 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:22.068506 23147 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.073s	user 0.025s	sys 0.012s
I20260812 06:19:22.181133 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushMRSOp(acfc8bb6b7364047a652d46a5122973e): perf score=15.086190
I20260812 06:19:22.341887 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushMRSOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.160s	user 0.126s	sys 0.031s Metrics: {"bytes_written":8533273,"cfile_init":1,"compiler_manager_pool.queue_time_us":199,"delete_count":0,"dirs.queue_time_us":93,"dirs.run_cpu_time_us":317,"dirs.run_wall_time_us":1351,"drs_written":1,"lbm_read_time_us":79,"lbm_reads_lt_1ms":4,"lbm_write_time_us":37665,"lbm_writes_lt_1ms":565,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":81280,"thread_start_us":126,"threads_started":1,"update_count":1040}
I20260812 06:19:22.343230 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling LogGCOp(acfc8bb6b7364047a652d46a5122973e): free 8725963 bytes of WAL
I20260812 06:19:22.343557 23269 log_reader.cc:385] T acfc8bb6b7364047a652d46a5122973e: removed 1 log segments from log reader
I20260812 06:19:22.343621 23269 log.cc:1079] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/acfc8bb6b7364047a652d46a5122973e/wal-000000001 (ops 1-6)
I20260812 06:19:22.346357 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: LogGCOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:22.346760 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling UndoDeltaBlockGCOp(acfc8bb6b7364047a652d46a5122973e): 12308959 bytes on disk
I20260812 06:19:22.347430 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: UndoDeltaBlockGCOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":79,"lbm_reads_lt_1ms":4}
I20260812 06:19:22.348088 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=2.188937
I20260812 06:19:22.377664 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.029s	user 0.011s	sys 0.005s Metrics: {"bytes_written":3774459,"delete_count":0,"lbm_write_time_us":6684,"lbm_writes_lt_1ms":95,"reinsert_count":0,"update_count":460}
I20260812 06:19:22.378278 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=2.188937
I20260812 06:19:22.395349 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.017s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6985,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:22.395913 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e): perf score=1.000000
I20260812 06:19:22.548216 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.152s	user 0.123s	sys 0.028s Metrics: {"cfile_cache_miss":433,"cfile_cache_miss_bytes":20631425,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1483,"lbm_read_time_us":10521,"lbm_reads_lt_1ms":469,"lbm_write_time_us":28214,"lbm_writes_lt_1ms":443,"mutex_wait_us":349,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":345,"threads_started":5,"update_count":2000}
I20260812 06:19:22.548866 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=10.126437
I20260812 06:19:22.597318 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.048s	user 0.017s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16099,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:22.597837 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=2.188937
I20260812 06:19:22.610618 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.013s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4616,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:22.611093 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e): perf score=1.000000
I20260812 06:19:22.746317 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.135s	user 0.108s	sys 0.026s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":623,"lbm_read_time_us":10476,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24962,"lbm_writes_lt_1ms":443,"mutex_wait_us":309,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16384,"update_count":2000}
I20260812 06:19:22.746872 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=10.126437
I20260812 06:19:22.795396 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.048s	user 0.029s	sys 0.012s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":14925,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:22.795977 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e): perf score=1.000000
I20260812 06:19:22.931484 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.135s	user 0.089s	sys 0.043s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528784,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"lbm_read_time_us":9373,"lbm_reads_lt_1ms":363,"lbm_write_time_us":22873,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:19:22.932229 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=10.126437
I20260812 06:19:22.976404 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.044s	user 0.029s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17003,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:22.976963 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=2.188937
I20260812 06:19:22.990693 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.014s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4645,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:22.991232 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e): perf score=1.000000
I20260812 06:19:23.120154 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.129s	user 0.095s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1171,"lbm_read_time_us":8966,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21874,"lbm_writes_lt_1ms":443,"mutex_wait_us":309,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15104,"update_count":2000}
I20260812 06:19:23.120890 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=10.126437
I20260812 06:19:23.170362 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.049s	user 0.017s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14914,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:23.170965 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=2.188937
I20260812 06:19:23.182297 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4158,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:23.183010 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e): perf score=1.000000
I20260812 06:19:23.308787 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.125s	user 0.108s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":858,"lbm_read_time_us":7832,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25143,"lbm_writes_lt_1ms":443,"mutex_wait_us":348,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2000}
I20260812 06:19:23.309507 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=10.126437
I20260812 06:19:23.364543 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.055s	user 0.025s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16175,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:23.365149 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=2.188937
I20260812 06:19:23.376976 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) 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:19:23.377492 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e): perf score=1.000000
I20260812 06:19:23.527405 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.150s	user 0.098s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":739,"lbm_read_time_us":11383,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24449,"lbm_writes_lt_1ms":443,"mutex_wait_us":85,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19200,"update_count":2000}
I20260812 06:19:23.528288 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=10.126437
I20260812 06:19:23.572232 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.044s	user 0.023s	sys 0.015s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17870,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:23.572855 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=2.188937
I20260812 06:19:23.585500 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4535,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:23.586325 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e): perf score=1.000000
I20260812 06:19:23.718024 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.132s	user 0.107s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":787,"lbm_read_time_us":10420,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25490,"lbm_writes_lt_1ms":443,"mutex_wait_us":64,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2000}
I20260812 06:19:23.718783 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=10.126437
I20260812 06:19:23.761322 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.042s	user 0.030s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16867,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:23.761940 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=2.188937
I20260812 06:19:23.773743 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4261,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:23.774533 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushMRSOp(acfc8bb6b7364047a652d46a5122973e): perf score=1.000000
I20260812 06:19:23.809162 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushMRSOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.034s	user 0.025s	sys 0.009s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":196,"dirs.run_wall_time_us":1465,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1828,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:23.809954 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling LogGCOp(acfc8bb6b7364047a652d46a5122973e): free 132571263 bytes of WAL
I20260812 06:19:23.810191 23269 log_reader.cc:385] T acfc8bb6b7364047a652d46a5122973e: removed 13 log segments from log reader
I20260812 06:19:23.810235 23269 log.cc:1079] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/acfc8bb6b7364047a652d46a5122973e/wal-000000002 (ops 7-11)
I20260812 06:19:23.810263 23269 log.cc:1079] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/acfc8bb6b7364047a652d46a5122973e/wal-000000003 (ops 12-16)
I20260812 06:19:23.810326 23269 log.cc:1079] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/acfc8bb6b7364047a652d46a5122973e/wal-000000004 (ops 17-21)
I20260812 06:19:23.810382 23269 log.cc:1079] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/acfc8bb6b7364047a652d46a5122973e/wal-000000005 (ops 22-26)
I20260812 06:19:23.810421 23269 log.cc:1079] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/acfc8bb6b7364047a652d46a5122973e/wal-000000006 (ops 27-31)
I20260812 06:19:23.810464 23269 log.cc:1079] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/acfc8bb6b7364047a652d46a5122973e/wal-000000007 (ops 32-36)
I20260812 06:19:23.810503 23269 log.cc:1079] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/acfc8bb6b7364047a652d46a5122973e/wal-000000008 (ops 37-40)
I20260812 06:19:23.810542 23269 log.cc:1079] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/acfc8bb6b7364047a652d46a5122973e/wal-000000009 (ops 41-45)
I20260812 06:19:23.810581 23269 log.cc:1079] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/acfc8bb6b7364047a652d46a5122973e/wal-000000010 (ops 46-50)
I20260812 06:19:23.810622 23269 log.cc:1079] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/acfc8bb6b7364047a652d46a5122973e/wal-000000011 (ops 51-55)
I20260812 06:19:23.810662 23269 log.cc:1079] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/acfc8bb6b7364047a652d46a5122973e/wal-000000012 (ops 56-60)
I20260812 06:19:23.810699 23269 log.cc:1079] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/acfc8bb6b7364047a652d46a5122973e/wal-000000013 (ops 61-64)
I20260812 06:19:23.810737 23269 log.cc:1079] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/acfc8bb6b7364047a652d46a5122973e/wal-000000014 (ops 65-69)
I20260812 06:19:23.841956 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: LogGCOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.032s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:19:23.842474 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=4.173312
I20260812 06:19:23.862677 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.020s	user 0.006s	sys 0.012s Metrics: {"bytes_written":6235917,"delete_count":0,"lbm_write_time_us":8375,"lbm_writes_lt_1ms":155,"reinsert_count":0,"update_count":760}
I20260812 06:19:23.863231 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=1.000000
I20260812 06:19:23.874166 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":1969352,"delete_count":0,"lbm_write_time_us":3612,"lbm_writes_lt_1ms":51,"reinsert_count":0,"update_count":240}
I20260812 06:19:23.874794 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e): perf score=1.000000
I20260812 06:19:24.067442 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.192s	user 0.138s	sys 0.044s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836320,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":290,"lbm_read_time_us":13722,"lbm_reads_lt_1ms":666,"lbm_write_time_us":38156,"lbm_writes_lt_1ms":643,"mutex_wait_us":24,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":73600,"thread_start_us":83,"threads_started":1,"update_count":3000}
I20260812 06:19:24.068176 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling UndoDeltaBlockGCOp(acfc8bb6b7364047a652d46a5122973e): 482 bytes on disk
I20260812 06:19:24.068833 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: UndoDeltaBlockGCOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":103,"lbm_reads_lt_1ms":4}
I20260812 06:19:24.069569 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=14.095187
I20260812 06:19:24.119992 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.050s	user 0.033s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19184,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:24.120482 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=2.188937
I20260812 06:19:24.132836 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4334,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:24.133616 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e): perf score=1.000000
I20260812 06:19:24.293404 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.160s	user 0.098s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":230,"lbm_read_time_us":9642,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29918,"lbm_writes_lt_1ms":543,"mutex_wait_us":59,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":35584,"update_count":2500}
I20260812 06:19:24.293987 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=14.095187
I20260812 06:19:24.357882 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.064s	user 0.032s	sys 0.020s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":24739,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:24.358415 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=2.188937
I20260812 06:19:24.371791 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4840,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:24.372331 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e): perf score=1.000000
I20260812 06:19:24.579139 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.207s	user 0.123s	sys 0.075s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733720,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":580,"lbm_read_time_us":13174,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34311,"lbm_writes_lt_1ms":543,"mutex_wait_us":300,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15360,"update_count":2500}
I20260812 06:19:24.579767 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=14.095187
I20260812 06:19:24.627146 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.047s	user 0.025s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21058,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:24.627952 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e): perf score=1.000000
I20260812 06:19:24.775521 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.147s	user 0.106s	sys 0.039s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631192,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":2024,"lbm_read_time_us":9311,"lbm_reads_lt_1ms":467,"lbm_write_time_us":24094,"lbm_writes_lt_1ms":443,"mutex_wait_us":434,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:24.776168 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=11.118625
I20260812 06:19:24.815204 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.039s	user 0.028s	sys 0.007s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17590,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:24.815740 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=2.188937
I20260812 06:19:24.827895 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4887,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:24.828419 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e): perf score=1.000000
I20260812 06:19:24.978217 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.150s	user 0.117s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":951,"lbm_read_time_us":9560,"lbm_reads_lt_1ms":472,"lbm_write_time_us":31439,"lbm_writes_lt_1ms":443,"mutex_wait_us":62,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2000}
I20260812 06:19:24.978976 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=10.126437
I20260812 06:19:25.022662 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.044s	user 0.013s	sys 0.025s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17569,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:25.023152 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=2.188937
I20260812 06:19:25.034194 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4072,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:25.034888 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e): perf score=1.000000
I20260812 06:19:25.158612 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.124s	user 0.105s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":197,"lbm_read_time_us":8394,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23413,"lbm_writes_lt_1ms":443,"mutex_wait_us":56,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":20352,"update_count":2000}
I20260812 06:19:25.159365 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=10.126437
I20260812 06:19:25.210793 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.051s	user 0.028s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18231,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:25.211364 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=2.188937
I20260812 06:19:25.223680 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4105,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:25.224419 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushMRSOp(acfc8bb6b7364047a652d46a5122973e): perf score=1.000000
I20260812 06:19:25.258580 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushMRSOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.034s	user 0.028s	sys 0.004s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":216,"dirs.run_wall_time_us":1420,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2008,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:25.259398 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling LogGCOp(acfc8bb6b7364047a652d46a5122973e): free 120553439 bytes of WAL
I20260812 06:19:25.259668 23269 log_reader.cc:385] T acfc8bb6b7364047a652d46a5122973e: removed 12 log segments from log reader
I20260812 06:19:25.259713 23269 log.cc:1079] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/acfc8bb6b7364047a652d46a5122973e/wal-000000015 (ops 70-74)
I20260812 06:19:25.259744 23269 log.cc:1079] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/acfc8bb6b7364047a652d46a5122973e/wal-000000016 (ops 75-78)
I20260812 06:19:25.259804 23269 log.cc:1079] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/acfc8bb6b7364047a652d46a5122973e/wal-000000017 (ops 79-83)
I20260812 06:19:25.259851 23269 log.cc:1079] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/acfc8bb6b7364047a652d46a5122973e/wal-000000018 (ops 84-88)
I20260812 06:19:25.259895 23269 log.cc:1079] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/acfc8bb6b7364047a652d46a5122973e/wal-000000019 (ops 89-93)
I20260812 06:19:25.259934 23269 log.cc:1079] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/acfc8bb6b7364047a652d46a5122973e/wal-000000020 (ops 94-98)
I20260812 06:19:25.259984 23269 log.cc:1079] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/acfc8bb6b7364047a652d46a5122973e/wal-000000021 (ops 99-103)
I20260812 06:19:25.260037 23269 log.cc:1079] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/acfc8bb6b7364047a652d46a5122973e/wal-000000022 (ops 104-108)
I20260812 06:19:25.260078 23269 log.cc:1079] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/acfc8bb6b7364047a652d46a5122973e/wal-000000023 (ops 109-112)
I20260812 06:19:25.260119 23269 log.cc:1079] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/acfc8bb6b7364047a652d46a5122973e/wal-000000024 (ops 113-117)
I20260812 06:19:25.260160 23269 log.cc:1079] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/acfc8bb6b7364047a652d46a5122973e/wal-000000025 (ops 118-122)
I20260812 06:19:25.260200 23269 log.cc:1079] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/acfc8bb6b7364047a652d46a5122973e/wal-000000026 (ops 123-127)
I20260812 06:19:25.289736 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: LogGCOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.030s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:19:25.290207 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling UndoDeltaBlockGCOp(acfc8bb6b7364047a652d46a5122973e): 447 bytes on disk
I20260812 06:19:25.290748 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: UndoDeltaBlockGCOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4}
I20260812 06:19:25.291409 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=3.181125
I20260812 06:19:25.304692 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4718026,"delete_count":0,"lbm_write_time_us":4887,"lbm_writes_lt_1ms":118,"reinsert_count":0,"update_count":575}
I20260812 06:19:25.305418 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=2.188937
I20260812 06:19:25.317397 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3487280,"delete_count":0,"lbm_write_time_us":4527,"lbm_writes_lt_1ms":88,"reinsert_count":0,"update_count":425}
I20260812 06:19:25.318225 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e): perf score=1.000000
I20260812 06:19:25.505267 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.187s	user 0.147s	sys 0.035s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836362,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":713,"lbm_read_time_us":14611,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36319,"lbm_writes_lt_1ms":643,"mutex_wait_us":326,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12288,"thread_start_us":80,"threads_started":1,"update_count":3000}
I20260812 06:19:25.506096 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=14.095187
I20260812 06:19:25.563350 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.056s	user 0.032s	sys 0.013s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21496,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:25.563908 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=2.188937
I20260812 06:19:25.578227 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.014s	user 0.004s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5846,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:25.578879 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e): perf score=1.000000
I20260812 06:19:25.747187 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.168s	user 0.113s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":817,"lbm_read_time_us":12194,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":571,"lbm_write_time_us":32636,"lbm_writes_lt_1ms":543,"mutex_wait_us":94,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":65536,"update_count":2500}
I20260812 06:19:25.748080 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=12.110812
I20260812 06:19:25.801770 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.053s	user 0.035s	sys 0.017s Metrics: {"bytes_written":13702313,"delete_count":0,"lbm_write_time_us":24614,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":336,"reinsert_count":0,"update_count":1670}
I20260812 06:19:25.802469 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=1.196750
I20260812 06:19:25.824821 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.022s	user 0.006s	sys 0.008s Metrics: {"bytes_written":3118059,"delete_count":0,"lbm_write_time_us":5326,"lbm_writes_lt_1ms":79,"reinsert_count":0,"update_count":380}
I20260812 06:19:25.825403 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=2.188937
I20260812 06:19:25.836309 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4049,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:25.836992 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e): perf score=1.000000
I20260812 06:19:26.024191 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.187s	user 0.130s	sys 0.056s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733812,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":559,"lbm_read_time_us":12231,"lbm_reads_lt_1ms":573,"lbm_write_time_us":35113,"lbm_writes_lt_1ms":543,"mutex_wait_us":59,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2500}
I20260812 06:19:26.024861 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=14.095187
I20260812 06:19:26.094771 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.070s	user 0.026s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26124,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:26.095335 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=2.188937
I20260812 06:19:26.106801 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4327,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:26.107390 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e): perf score=1.000000
I20260812 06:19:26.291270 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.184s	user 0.107s	sys 0.074s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":391,"lbm_read_time_us":13981,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33030,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:26.291900 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=11.118625
I20260812 06:19:26.343407 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.048s	user 0.030s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16246,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:26.344213 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=2.188937
I20260812 06:19:26.359970 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.016s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4710,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:26.360492 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e): perf score=1.000000
I20260812 06:19:26.514649 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.154s	user 0.097s	sys 0.045s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":387,"lbm_read_time_us":9900,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22604,"lbm_writes_lt_1ms":443,"mutex_wait_us":44,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":31872,"update_count":2000}
I20260812 06:19:26.515424 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=14.095187
I20260812 06:19:26.570241 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.055s	user 0.035s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19429,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:26.570768 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=2.188937
I20260812 06:19:26.581768 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3968,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:26.582401 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e): perf score=1.000000
I20260812 06:19:26.749977 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.167s	user 0.135s	sys 0.031s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":950,"lbm_read_time_us":13041,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33560,"lbm_writes_lt_1ms":543,"mutex_wait_us":267,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17664,"update_count":2500}
I20260812 06:19:26.750676 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=10.126437
I20260812 06:19:26.796226 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.045s	user 0.024s	sys 0.017s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":20602,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":300,"reinsert_count":0,"update_count":1500}
I20260812 06:19:26.796850 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=2.188937
I20260812 06:19:26.823982 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.027s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5906,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:26.824530 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=2.188937
I20260812 06:19:26.839267 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5780,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:26.839960 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushMRSOp(acfc8bb6b7364047a652d46a5122973e): perf score=1.000000
I20260812 06:19:26.871369 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushMRSOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":216,"dirs.run_wall_time_us":1668,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2029,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:26.872133 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling LogGCOp(acfc8bb6b7364047a652d46a5122973e): free 124257518 bytes of WAL
I20260812 06:19:26.872427 23269 log_reader.cc:385] T acfc8bb6b7364047a652d46a5122973e: removed 12 log segments from log reader
I20260812 06:19:26.872499 23269 log.cc:1079] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/acfc8bb6b7364047a652d46a5122973e/wal-000000027 (ops 128-132)
I20260812 06:19:26.872566 23269 log.cc:1079] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/acfc8bb6b7364047a652d46a5122973e/wal-000000028 (ops 133-137)
I20260812 06:19:26.872598 23269 log.cc:1079] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/acfc8bb6b7364047a652d46a5122973e/wal-000000029 (ops 138-142)
I20260812 06:19:26.872622 23269 log.cc:1079] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/acfc8bb6b7364047a652d46a5122973e/wal-000000030 (ops 143-147)
I20260812 06:19:26.872649 23269 log.cc:1079] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/acfc8bb6b7364047a652d46a5122973e/wal-000000031 (ops 148-152)
I20260812 06:19:26.872684 23269 log.cc:1079] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/acfc8bb6b7364047a652d46a5122973e/wal-000000032 (ops 153-157)
I20260812 06:19:26.872716 23269 log.cc:1079] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/acfc8bb6b7364047a652d46a5122973e/wal-000000033 (ops 158-162)
I20260812 06:19:26.872746 23269 log.cc:1079] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/acfc8bb6b7364047a652d46a5122973e/wal-000000034 (ops 163-166)
I20260812 06:19:26.872767 23269 log.cc:1079] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/acfc8bb6b7364047a652d46a5122973e/wal-000000035 (ops 167-171)
I20260812 06:19:26.872797 23269 log.cc:1079] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/acfc8bb6b7364047a652d46a5122973e/wal-000000036 (ops 172-176)
I20260812 06:19:26.872824 23269 log.cc:1079] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/acfc8bb6b7364047a652d46a5122973e/wal-000000037 (ops 177-181)
I20260812 06:19:26.872859 23269 log.cc:1079] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/acfc8bb6b7364047a652d46a5122973e/wal-000000038 (ops 182-186)
I20260812 06:19:26.903299 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: LogGCOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.031s	user 0.001s	sys 0.027s Metrics: {}
I20260812 06:19:26.903834 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=2.188937
I20260812 06:19:26.927583 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.024s	user 0.003s	sys 0.012s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6495,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:26.928097 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling UndoDeltaBlockGCOp(acfc8bb6b7364047a652d46a5122973e): 482 bytes on disk
I20260812 06:19:26.928725 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: UndoDeltaBlockGCOp(acfc8bb6b7364047a652d46a5122973e) 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:19:26.929463 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=2.188937
I20260812 06:19:26.951727 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.022s	user 0.011s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5078,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:26.952365 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e): perf score=1.000000
I20260812 06:19:27.183964 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.231s	user 0.150s	sys 0.081s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32938901,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":244,"lbm_read_time_us":17370,"lbm_reads_lt_1ms":775,"lbm_write_time_us":40322,"lbm_writes_lt_1ms":743,"mutex_wait_us":261,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":102,"threads_started":1,"update_count":3500}
I20260812 06:19:27.184695 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=14.095187
I20260812 06:19:27.225255 23147 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.157s	user 1.867s	sys 0.149s
I20260812 06:19:27.253389 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.069s	user 0.043s	sys 0.025s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":31387,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:27.254143 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e): perf score=2.188937
I20260812 06:19:27.268240 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: FlushDeltaMemStoresOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.014s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5512,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:27.268816 23346 maintenance_manager.cc:419] P 56717fd1fc1d414ea8e901573279f261: Scheduling MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e): perf score=1.000000
I20260812 06:19:27.288691 23147 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.063s	user 0.006s	sys 0.000s
I20260812 06:19:27.289680 23147 tablet_server.cc:179] TabletServer@127.22.154.193:0 shutting down...
I20260812 06:19:27.424855 23269 maintenance_manager.cc:643] P 56717fd1fc1d414ea8e901573279f261: MajorDeltaCompactionOp(acfc8bb6b7364047a652d46a5122973e) complete. Timing: real 0.156s	user 0.098s	sys 0.056s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4221425,"cfile_cache_miss":502,"cfile_cache_miss_bytes":20512299,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":267,"lbm_read_time_us":9536,"lbm_reads_lt_1ms":518,"lbm_write_time_us":25419,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":22272,"update_count":2500}
I20260812 06:19:27.425921 23147 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:27.426401 23147 tablet_replica.cc:333] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261: stopping tablet replica
I20260812 06:19:27.426661 23147 raft_consensus.cc:2243] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:27.426930 23147 raft_consensus.cc:2272] T acfc8bb6b7364047a652d46a5122973e P 56717fd1fc1d414ea8e901573279f261 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:27.443552 23147 tablet_server.cc:196] TabletServer@127.22.154.193:0 shutdown complete.
I20260812 06:19:27.472733 23147 master.cc:562] Master@127.22.154.254:35941 shutting down...
I20260812 06:19:27.477110 23147 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 410df3f933eb4403996058f674ae6cc3 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:27.477373 23147 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 410df3f933eb4403996058f674ae6cc3 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:27.477502 23147 tablet_replica.cc:333] T 00000000000000000000000000000000 P 410df3f933eb4403996058f674ae6cc3: stopping tablet replica
I20260812 06:19:27.490454 23147 master.cc:584] Master@127.22.154.254:35941 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5828 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:27.583644 23147 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.22.154.254:39359
I20260812 06:19:27.584075 23147 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:19:27.587205 23147 server_base.cc:1061] running on GCE node
W20260812 06:19:27.587271 23381 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:19:27.587364 23383 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:19:27.587271 23380 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:27.587690 23147 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:27.587734 23147 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:19:27.587749 23147 hybrid_clock.cc:648] HybridClock initialized: now 1786515567587750 us; error 0 us; skew 500 ppm
I20260812 06:19:27.589042 23147 webserver.cc:533] Webserver started at http://127.22.154.254:40829/ using document root <none> and password file <none>
I20260812 06:19:27.589239 23147 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:27.589288 23147 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:27.589396 23147 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:27.589831 23147 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/master-0-root/instance:
uuid: "096d548d13a344b8b3ff22fe8c043548"
format_stamp: "Formatted at 2026-08-12 06:19:27 on dist-test-slave-rnrw"
I20260812 06:19:27.591488 23147 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:27.592712 23391 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:19:27.593119 23147 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:27.593227 23147 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/master-0-root
uuid: "096d548d13a344b8b3ff22fe8c043548"
format_stamp: "Formatted at 2026-08-12 06:19:27 on dist-test-slave-rnrw"
I20260812 06:19:27.593298 23147 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-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:19:27.613590 23147 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:27.613997 23147 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:27.618299 23147 rpc_server.cc:307] RPC server started. Bound to: 127.22.154.254:39359
I20260812 06:19:27.636472 23450 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.22.154.254:39359 every 8 connection(s)
I20260812 06:19:27.637101 23451 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:19:27.638945 23451 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 096d548d13a344b8b3ff22fe8c043548: Bootstrap starting.
I20260812 06:19:27.639734 23451 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 096d548d13a344b8b3ff22fe8c043548: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:27.640877 23451 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 096d548d13a344b8b3ff22fe8c043548: No bootstrap required, opened a new log
I20260812 06:19:27.641304 23451 raft_consensus.cc:359] T 00000000000000000000000000000000 P 096d548d13a344b8b3ff22fe8c043548 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "096d548d13a344b8b3ff22fe8c043548" member_type: VOTER }
I20260812 06:19:27.641395 23451 raft_consensus.cc:385] T 00000000000000000000000000000000 P 096d548d13a344b8b3ff22fe8c043548 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:27.641429 23451 raft_consensus.cc:740] T 00000000000000000000000000000000 P 096d548d13a344b8b3ff22fe8c043548 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 096d548d13a344b8b3ff22fe8c043548, State: Initialized, Role: FOLLOWER
I20260812 06:19:27.641594 23451 consensus_queue.cc:260] T 00000000000000000000000000000000 P 096d548d13a344b8b3ff22fe8c043548 [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: "096d548d13a344b8b3ff22fe8c043548" member_type: VOTER }
I20260812 06:19:27.641690 23451 raft_consensus.cc:399] T 00000000000000000000000000000000 P 096d548d13a344b8b3ff22fe8c043548 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:27.641716 23451 raft_consensus.cc:493] T 00000000000000000000000000000000 P 096d548d13a344b8b3ff22fe8c043548 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:27.641744 23451 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 096d548d13a344b8b3ff22fe8c043548 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:27.642462 23451 raft_consensus.cc:515] T 00000000000000000000000000000000 P 096d548d13a344b8b3ff22fe8c043548 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "096d548d13a344b8b3ff22fe8c043548" member_type: VOTER }
I20260812 06:19:27.642594 23451 leader_election.cc:304] T 00000000000000000000000000000000 P 096d548d13a344b8b3ff22fe8c043548 [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: 096d548d13a344b8b3ff22fe8c043548; no voters: 
I20260812 06:19:27.642760 23451 leader_election.cc:290] T 00000000000000000000000000000000 P 096d548d13a344b8b3ff22fe8c043548 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:27.642932 23456 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 096d548d13a344b8b3ff22fe8c043548 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:27.643143 23456 raft_consensus.cc:697] T 00000000000000000000000000000000 P 096d548d13a344b8b3ff22fe8c043548 [term 1 LEADER]: Becoming Leader. State: Replica: 096d548d13a344b8b3ff22fe8c043548, State: Running, Role: LEADER
I20260812 06:19:27.643275 23451 sys_catalog.cc:565] T 00000000000000000000000000000000 P 096d548d13a344b8b3ff22fe8c043548 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:27.643306 23456 consensus_queue.cc:237] T 00000000000000000000000000000000 P 096d548d13a344b8b3ff22fe8c043548 [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: "096d548d13a344b8b3ff22fe8c043548" member_type: VOTER }
I20260812 06:19:27.643790 23460 sys_catalog.cc:455] T 00000000000000000000000000000000 P 096d548d13a344b8b3ff22fe8c043548 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 096d548d13a344b8b3ff22fe8c043548. Latest consensus state: current_term: 1 leader_uuid: "096d548d13a344b8b3ff22fe8c043548" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "096d548d13a344b8b3ff22fe8c043548" member_type: VOTER } }
I20260812 06:19:27.643769 23459 sys_catalog.cc:455] T 00000000000000000000000000000000 P 096d548d13a344b8b3ff22fe8c043548 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "096d548d13a344b8b3ff22fe8c043548" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "096d548d13a344b8b3ff22fe8c043548" member_type: VOTER } }
I20260812 06:19:27.643900 23460 sys_catalog.cc:458] T 00000000000000000000000000000000 P 096d548d13a344b8b3ff22fe8c043548 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:27.643932 23459 sys_catalog.cc:458] T 00000000000000000000000000000000 P 096d548d13a344b8b3ff22fe8c043548 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:27.644200 23464 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:27.645303 23464 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:27.645460 23147 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:27.647274 23464 catalog_manager.cc:1383] Generated new cluster ID: 244fefe60fc346468bb6c5f0edbdd7af
I20260812 06:19:27.647346 23464 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:27.657122 23464 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:27.657675 23464 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:27.670492 23464 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 096d548d13a344b8b3ff22fe8c043548: Generated new TSK 0
I20260812 06:19:27.670710 23464 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:27.678297 23147 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:27.680665 23481 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:19:27.680776 23479 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:19:27.680747 23147 server_base.cc:1061] running on GCE node
W20260812 06:19:27.680840 23478 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:27.681191 23147 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:27.681243 23147 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:19:27.681262 23147 hybrid_clock.cc:648] HybridClock initialized: now 1786515567681261 us; error 0 us; skew 500 ppm
I20260812 06:19:27.682134 23147 webserver.cc:533] Webserver started at http://127.22.154.193:45479/ using document root <none> and password file <none>
I20260812 06:19:27.682282 23147 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:27.682334 23147 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:27.682480 23147 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:27.683239 23147 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root/instance:
uuid: "4d5d8512492f4673b87b7b00bb0d646c"
format_stamp: "Formatted at 2026-08-12 06:19:27 on dist-test-slave-rnrw"
I20260812 06:19:27.685272 23147 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:27.686436 23489 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:19:27.686718 23147 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:27.686815 23147 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root
uuid: "4d5d8512492f4673b87b7b00bb0d646c"
format_stamp: "Formatted at 2026-08-12 06:19:27 on dist-test-slave-rnrw"
I20260812 06:19:27.686929 23147 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-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:19:27.692341 23147 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:27.692819 23147 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:27.693157 23147 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:27.693652 23147 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:27.693712 23147 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:27.693775 23147 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:27.693823 23147 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:27.699090 23147 rpc_server.cc:307] RPC server started. Bound to: 127.22.154.193:38329
I20260812 06:19:27.699168 23574 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.22.154.193:38329 every 8 connection(s)
I20260812 06:19:27.710628 23575 heartbeater.cc:344] Connected to a master server at 127.22.154.254:39359
I20260812 06:19:27.710772 23575 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:27.711095 23575 heartbeater.cc:507] Master 127.22.154.254:39359 requested a full tablet report, sending...
I20260812 06:19:27.711959 23411 ts_manager.cc:194] Registered new tserver with Master: 4d5d8512492f4673b87b7b00bb0d646c (127.22.154.193:38329)
I20260812 06:19:27.712196 23147 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012549892s
I20260812 06:19:27.713142 23411 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:59512
I20260812 06:19:27.721582 23411 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:59518:
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:19:27.731827 23526 tablet_service.cc:1511] Processing CreateTablet for tablet b35344dca0a94231b2012321e7063c0a (DEFAULT_TABLE table=heavy-update-compaction-test [id=5475b266504e4df2a58b8c9f545bcb56]), partition=
I20260812 06:19:27.732239 23526 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet b35344dca0a94231b2012321e7063c0a. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:27.734928 23589 tablet_bootstrap.cc:492] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Bootstrap starting.
I20260812 06:19:27.735898 23589 tablet_bootstrap.cc:654] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:27.737421 23589 tablet_bootstrap.cc:492] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: No bootstrap required, opened a new log
I20260812 06:19:27.737600 23589 ts_tablet_manager.cc:1403] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:27.738145 23589 raft_consensus.cc:359] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4d5d8512492f4673b87b7b00bb0d646c" member_type: VOTER last_known_addr { host: "127.22.154.193" port: 38329 } }
I20260812 06:19:27.738263 23589 raft_consensus.cc:385] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:27.738312 23589 raft_consensus.cc:740] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4d5d8512492f4673b87b7b00bb0d646c, State: Initialized, Role: FOLLOWER
I20260812 06:19:27.738482 23589 consensus_queue.cc:260] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c [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: "4d5d8512492f4673b87b7b00bb0d646c" member_type: VOTER last_known_addr { host: "127.22.154.193" port: 38329 } }
I20260812 06:19:27.738605 23589 raft_consensus.cc:399] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:27.738656 23589 raft_consensus.cc:493] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:27.738711 23589 raft_consensus.cc:3060] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:27.739540 23589 raft_consensus.cc:515] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4d5d8512492f4673b87b7b00bb0d646c" member_type: VOTER last_known_addr { host: "127.22.154.193" port: 38329 } }
I20260812 06:19:27.739706 23589 leader_election.cc:304] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c [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: 4d5d8512492f4673b87b7b00bb0d646c; no voters: 
I20260812 06:19:27.739957 23589 leader_election.cc:290] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:27.740171 23591 raft_consensus.cc:2804] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:27.740327 23589 ts_tablet_manager.cc:1434] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:27.740350 23575 heartbeater.cc:499] Master 127.22.154.254:39359 was elected leader, sending a full tablet report...
I20260812 06:19:27.740458 23591 raft_consensus.cc:697] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c [term 1 LEADER]: Becoming Leader. State: Replica: 4d5d8512492f4673b87b7b00bb0d646c, State: Running, Role: LEADER
I20260812 06:19:27.740676 23591 consensus_queue.cc:237] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c [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: "4d5d8512492f4673b87b7b00bb0d646c" member_type: VOTER last_known_addr { host: "127.22.154.193" port: 38329 } }
I20260812 06:19:27.742267 23411 catalog_manager.cc:5719] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c reported cstate change: term changed from 0 to 1, leader changed from <none> to 4d5d8512492f4673b87b7b00bb0d646c (127.22.154.193). New cstate: current_term: 1 leader_uuid: "4d5d8512492f4673b87b7b00bb0d646c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4d5d8512492f4673b87b7b00bb0d646c" member_type: VOTER last_known_addr { host: "127.22.154.193" port: 38329 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:27.814078 23147 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.065s	user 0.014s	sys 0.012s
I20260812 06:19:27.950287 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushMRSOp(b35344dca0a94231b2012321e7063c0a): perf score=15.086190
I20260812 06:19:28.078660 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushMRSOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.128s	user 0.102s	sys 0.024s Metrics: {"bytes_written":8820440,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":231,"dirs.run_wall_time_us":968,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":30476,"lbm_writes_lt_1ms":572,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"spinlock_wait_cycles":23168,"update_count":1075}
I20260812 06:19:28.079522 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling LogGCOp(b35344dca0a94231b2012321e7063c0a): free 11976772 bytes of WAL
I20260812 06:19:28.079875 23496 log_reader.cc:385] T b35344dca0a94231b2012321e7063c0a: removed 1 log segments from log reader
I20260812 06:19:28.079950 23496 log.cc:1079] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/b35344dca0a94231b2012321e7063c0a/wal-000000001 (ops 1-6)
I20260812 06:19:28.082736 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: LogGCOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:28.083168 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=2.188937
I20260812 06:19:28.098181 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3487280,"delete_count":0,"lbm_write_time_us":5801,"lbm_writes_lt_1ms":88,"reinsert_count":0,"update_count":425}
I20260812 06:19:28.098652 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling UndoDeltaBlockGCOp(b35344dca0a94231b2012321e7063c0a): 12308959 bytes on disk
I20260812 06:19:28.099076 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: UndoDeltaBlockGCOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:19:28.099475 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a): perf score=1.000000
I20260812 06:19:28.229650 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.130s	user 0.105s	sys 0.023s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528883,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":916,"lbm_read_time_us":8156,"lbm_reads_lt_1ms":364,"lbm_write_time_us":22345,"lbm_writes_lt_1ms":343,"mutex_wait_us":24,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":4736,"thread_start_us":392,"threads_started":5,"update_count":1500}
I20260812 06:19:28.230409 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=10.126437
I20260812 06:19:28.270416 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.040s	user 0.022s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17603,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:28.271077 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a): perf score=1.000000
I20260812 06:19:28.403496 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.132s	user 0.089s	sys 0.040s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528781,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":202,"lbm_read_time_us":10137,"lbm_reads_lt_1ms":367,"lbm_write_time_us":21628,"lbm_writes_lt_1ms":343,"mutex_wait_us":67,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":1500}
I20260812 06:19:28.404217 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=10.126437
I20260812 06:19:28.454720 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.050s	user 0.010s	sys 0.028s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17693,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:28.455240 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=2.188937
I20260812 06:19:28.468012 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4894,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:28.468678 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a): perf score=1.000000
I20260812 06:19:28.602052 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.133s	user 0.108s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":193,"lbm_read_time_us":8478,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25291,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16640,"update_count":2000}
I20260812 06:19:28.602763 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=10.126437
I20260812 06:19:28.654369 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.051s	user 0.033s	sys 0.016s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":21833,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:28.655022 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=2.188937
I20260812 06:19:28.674911 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.020s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5940,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:28.675462 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a): perf score=1.000000
I20260812 06:19:28.802143 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.126s	user 0.103s	sys 0.022s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":152,"lbm_read_time_us":8237,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23835,"lbm_writes_lt_1ms":443,"mutex_wait_us":32,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2000}
I20260812 06:19:28.802871 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=11.118625
I20260812 06:19:28.849351 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.046s	user 0.021s	sys 0.024s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15660,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:28.849979 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=2.188937
I20260812 06:19:28.862464 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.012s	user 0.010s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4589,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:28.863001 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a): perf score=1.000000
I20260812 06:19:29.028326 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.165s	user 0.103s	sys 0.061s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631304,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":160,"lbm_read_time_us":12517,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26173,"lbm_writes_lt_1ms":443,"mutex_wait_us":50,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":72064,"update_count":2000}
I20260812 06:19:29.029066 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=11.118625
I20260812 06:19:29.066746 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.037s	user 0.027s	sys 0.009s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":16499,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:29.067502 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=2.188937
I20260812 06:19:29.081022 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5034,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:29.081691 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a): perf score=1.000000
I20260812 06:19:29.223286 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.141s	user 0.101s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631304,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":270,"lbm_read_time_us":10602,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26379,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16768,"update_count":2000}
I20260812 06:19:29.224093 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=10.126437
I20260812 06:19:29.260725 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.036s	user 0.033s	sys 0.003s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15477,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:29.261251 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=2.188937
I20260812 06:19:29.272224 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4219,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:29.272835 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a): perf score=1.000000
I20260812 06:19:29.405462 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.132s	user 0.094s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":400,"lbm_read_time_us":9278,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23472,"lbm_writes_lt_1ms":443,"mutex_wait_us":65,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9856,"update_count":2000}
I20260812 06:19:29.406102 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=10.126437
I20260812 06:19:29.448609 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.042s	user 0.024s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15069,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:29.449321 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=2.188937
I20260812 06:19:29.461685 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4383,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:29.462369 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushMRSOp(b35344dca0a94231b2012321e7063c0a): perf score=1.000000
I20260812 06:19:29.496393 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushMRSOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.034s	user 0.028s	sys 0.004s Metrics: {"bytes_written":1234474,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":219,"dirs.run_wall_time_us":1673,"drs_written":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1707,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:29.497169 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling LogGCOp(b35344dca0a94231b2012321e7063c0a): free 121006423 bytes of WAL
I20260812 06:19:29.497512 23496 log_reader.cc:385] T b35344dca0a94231b2012321e7063c0a: removed 12 log segments from log reader
I20260812 06:19:29.497596 23496 log.cc:1079] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/b35344dca0a94231b2012321e7063c0a/wal-000000002 (ops 7-11)
I20260812 06:19:29.497653 23496 log.cc:1079] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/b35344dca0a94231b2012321e7063c0a/wal-000000003 (ops 12-16)
I20260812 06:19:29.497712 23496 log.cc:1079] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/b35344dca0a94231b2012321e7063c0a/wal-000000004 (ops 17-20)
I20260812 06:19:29.497757 23496 log.cc:1079] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/b35344dca0a94231b2012321e7063c0a/wal-000000005 (ops 21-25)
I20260812 06:19:29.497799 23496 log.cc:1079] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/b35344dca0a94231b2012321e7063c0a/wal-000000006 (ops 26-30)
I20260812 06:19:29.497839 23496 log.cc:1079] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/b35344dca0a94231b2012321e7063c0a/wal-000000007 (ops 31-35)
I20260812 06:19:29.497880 23496 log.cc:1079] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/b35344dca0a94231b2012321e7063c0a/wal-000000008 (ops 36-40)
I20260812 06:19:29.497920 23496 log.cc:1079] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/b35344dca0a94231b2012321e7063c0a/wal-000000009 (ops 41-45)
I20260812 06:19:29.497958 23496 log.cc:1079] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/b35344dca0a94231b2012321e7063c0a/wal-000000010 (ops 46-50)
I20260812 06:19:29.497982 23496 log.cc:1079] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/b35344dca0a94231b2012321e7063c0a/wal-000000011 (ops 51-55)
I20260812 06:19:29.498015 23496 log.cc:1079] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/b35344dca0a94231b2012321e7063c0a/wal-000000012 (ops 56-60)
I20260812 06:19:29.498055 23496 log.cc:1079] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/b35344dca0a94231b2012321e7063c0a/wal-000000013 (ops 61-65)
I20260812 06:19:29.527801 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: LogGCOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.030s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:19:29.528913 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling UndoDeltaBlockGCOp(b35344dca0a94231b2012321e7063c0a): 472 bytes on disk
I20260812 06:19:29.530014 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: UndoDeltaBlockGCOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:19:29.530635 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=3.181125
I20260812 06:19:29.547847 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.017s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":5175,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:29.548331 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling LogGCOp(b35344dca0a94231b2012321e7063c0a): free 12017932 bytes of WAL
I20260812 06:19:29.548591 23496 log_reader.cc:385] T b35344dca0a94231b2012321e7063c0a: removed 1 log segments from log reader
I20260812 06:19:29.548645 23496 log.cc:1079] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/b35344dca0a94231b2012321e7063c0a/wal-000000014 (ops 66-70)
I20260812 06:19:29.551290 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: LogGCOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:29.551777 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=2.188937
I20260812 06:19:29.563788 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3948,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:29.564653 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a): perf score=1.000000
I20260812 06:19:29.759037 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.194s	user 0.142s	sys 0.051s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836361,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":212,"lbm_read_time_us":17291,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31960,"lbm_writes_lt_1ms":643,"mutex_wait_us":62,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":824192,"thread_start_us":97,"threads_started":1,"update_count":3000}
I20260812 06:19:29.759780 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=14.095187
I20260812 06:19:29.819092 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.059s	user 0.033s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25665,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:29.819685 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=2.188937
I20260812 06:19:29.846626 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.027s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6890,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:29.847170 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=2.188937
I20260812 06:19:29.858376 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4225,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:29.858965 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a): perf score=1.000000
I20260812 06:19:30.040841 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.182s	user 0.152s	sys 0.028s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836255,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":784,"lbm_read_time_us":12918,"lbm_reads_lt_1ms":673,"lbm_write_time_us":37327,"lbm_writes_lt_1ms":643,"mutex_wait_us":92,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3000}
I20260812 06:19:30.041579 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=14.095187
I20260812 06:19:30.091408 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.050s	user 0.026s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21459,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:30.091990 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=2.188937
I20260812 06:19:30.108929 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.017s	user 0.013s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6557,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:30.109681 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a): perf score=1.000000
I20260812 06:19:30.276240 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.166s	user 0.124s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":669,"lbm_read_time_us":10818,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33075,"lbm_writes_lt_1ms":543,"mutex_wait_us":338,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":23936,"update_count":2500}
I20260812 06:19:30.276942 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=12.110812
I20260812 06:19:30.321420 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.044s	user 0.024s	sys 0.019s Metrics: {"bytes_written":13743339,"delete_count":0,"lbm_write_time_us":19641,"lbm_writes_lt_1ms":338,"reinsert_count":0,"update_count":1675}
I20260812 06:19:30.322227 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=1.196750
I20260812 06:19:30.334434 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":2666779,"delete_count":0,"lbm_write_time_us":4187,"lbm_writes_lt_1ms":68,"reinsert_count":0,"update_count":325}
I20260812 06:19:30.334985 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a): perf score=1.000000
I20260812 06:19:30.494297 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.159s	user 0.111s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631281,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":71,"lbm_read_time_us":13511,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25498,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":39680,"update_count":2000}
I20260812 06:19:30.495190 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=10.126437
I20260812 06:19:30.539260 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.044s	user 0.029s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18438,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:30.540093 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=2.188937
I20260812 06:19:30.558431 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.018s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7157,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:30.559010 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a): perf score=1.000000
I20260812 06:19:30.699604 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.140s	user 0.087s	sys 0.051s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":255,"lbm_read_time_us":8604,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26709,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:30.700523 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=10.126437
I20260812 06:19:30.749893 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.049s	user 0.033s	sys 0.005s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17273,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:30.750497 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=2.188937
I20260812 06:19:30.763942 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4770,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:30.764668 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a): perf score=1.000000
I20260812 06:19:30.905292 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.140s	user 0.128s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":987,"lbm_read_time_us":10486,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26327,"lbm_writes_lt_1ms":443,"mutex_wait_us":119,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18944,"update_count":2000}
I20260812 06:19:30.905990 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=10.126437
I20260812 06:19:30.955825 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.050s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17298,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:30.956364 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=2.188937
I20260812 06:19:30.968824 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.012s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4196,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:30.969477 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushMRSOp(b35344dca0a94231b2012321e7063c0a): perf score=1.000000
I20260812 06:19:31.002002 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushMRSOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.032s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":242,"dirs.run_wall_time_us":1434,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1521,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:31.002692 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling LogGCOp(b35344dca0a94231b2012321e7063c0a): free 116849521 bytes of WAL
I20260812 06:19:31.002929 23496 log_reader.cc:385] T b35344dca0a94231b2012321e7063c0a: removed 12 log segments from log reader
I20260812 06:19:31.002993 23496 log.cc:1079] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/b35344dca0a94231b2012321e7063c0a/wal-000000015 (ops 71-75)
I20260812 06:19:31.003046 23496 log.cc:1079] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/b35344dca0a94231b2012321e7063c0a/wal-000000016 (ops 76-80)
I20260812 06:19:31.003108 23496 log.cc:1079] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/b35344dca0a94231b2012321e7063c0a/wal-000000017 (ops 81-84)
I20260812 06:19:31.003151 23496 log.cc:1079] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/b35344dca0a94231b2012321e7063c0a/wal-000000018 (ops 85-89)
I20260812 06:19:31.003187 23496 log.cc:1079] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/b35344dca0a94231b2012321e7063c0a/wal-000000019 (ops 90-94)
I20260812 06:19:31.003226 23496 log.cc:1079] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/b35344dca0a94231b2012321e7063c0a/wal-000000020 (ops 95-99)
I20260812 06:19:31.003271 23496 log.cc:1079] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/b35344dca0a94231b2012321e7063c0a/wal-000000021 (ops 100-104)
I20260812 06:19:31.003310 23496 log.cc:1079] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/b35344dca0a94231b2012321e7063c0a/wal-000000022 (ops 105-108)
I20260812 06:19:31.003350 23496 log.cc:1079] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/b35344dca0a94231b2012321e7063c0a/wal-000000023 (ops 109-113)
I20260812 06:19:31.003389 23496 log.cc:1079] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/b35344dca0a94231b2012321e7063c0a/wal-000000024 (ops 114-118)
I20260812 06:19:31.003429 23496 log.cc:1079] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/b35344dca0a94231b2012321e7063c0a/wal-000000025 (ops 119-122)
I20260812 06:19:31.003469 23496 log.cc:1079] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/b35344dca0a94231b2012321e7063c0a/wal-000000026 (ops 123-127)
I20260812 06:19:31.030000 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: LogGCOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:31.030474 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=3.181125
I20260812 06:19:31.042982 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":5160,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:31.043432 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=2.188937
I20260812 06:19:31.055080 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4072,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:31.056143 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a): perf score=1.000000
I20260812 06:19:31.228865 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.172s	user 0.131s	sys 0.039s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836360,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":341,"lbm_read_time_us":13869,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31777,"lbm_writes_lt_1ms":643,"mutex_wait_us":23,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":23808,"thread_start_us":79,"threads_started":1,"update_count":3000}
I20260812 06:19:31.229892 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling UndoDeltaBlockGCOp(b35344dca0a94231b2012321e7063c0a): 462 bytes on disk
I20260812 06:19:31.230579 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: UndoDeltaBlockGCOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":81,"lbm_reads_lt_1ms":4}
I20260812 06:19:31.231879 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=14.095187
I20260812 06:19:31.278733 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.047s	user 0.037s	sys 0.007s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20764,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1399040,"update_count":2000}
I20260812 06:19:31.279297 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=2.188937
I20260812 06:19:31.295529 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.016s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6174,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:31.296077 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a): perf score=1.000000
I20260812 06:19:31.466097 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.170s	user 0.120s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":267,"lbm_read_time_us":11697,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30144,"lbm_writes_lt_1ms":543,"mutex_wait_us":72,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:19:31.466876 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=14.095187
I20260812 06:19:31.527508 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.060s	user 0.023s	sys 0.031s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26524,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:31.528035 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a): perf score=1.000000
I20260812 06:19:31.694598 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.166s	user 0.130s	sys 0.032s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631192,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":170,"lbm_read_time_us":11862,"lbm_reads_lt_1ms":463,"lbm_write_time_us":27151,"lbm_writes_lt_1ms":443,"mutex_wait_us":51,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2000}
I20260812 06:19:31.695362 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=14.095187
I20260812 06:19:31.744438 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.049s	user 0.031s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21999,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:31.745236 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=2.188937
I20260812 06:19:31.758222 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5180,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:31.758754 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a): perf score=1.000000
I20260812 06:19:31.949062 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.190s	user 0.123s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":292,"lbm_read_time_us":12834,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32306,"lbm_writes_lt_1ms":543,"mutex_wait_us":51,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":2500}
I20260812 06:19:31.949805 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=11.118625
I20260812 06:19:31.989691 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.040s	user 0.031s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17268,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:31.990244 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=2.188937
I20260812 06:19:32.002702 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4258,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:32.003304 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a): perf score=1.000000
I20260812 06:19:32.135038 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.132s	user 0.109s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":332,"lbm_read_time_us":9422,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24164,"lbm_writes_lt_1ms":443,"mutex_wait_us":61,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19072,"update_count":2000}
I20260812 06:19:32.135763 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=10.126437
I20260812 06:19:32.187405 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.051s	user 0.031s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18204,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:32.188009 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=2.188937
I20260812 06:19:32.198993 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4058,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:32.199506 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a): perf score=1.000000
I20260812 06:19:32.326603 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.127s	user 0.102s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":310,"lbm_read_time_us":9355,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22767,"lbm_writes_lt_1ms":443,"mutex_wait_us":52,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:19:32.327317 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=10.126437
I20260812 06:19:32.381510 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.054s	user 0.030s	sys 0.023s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":20671,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:32.382081 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=2.188937
I20260812 06:19:32.393375 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4433,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:32.394062 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushMRSOp(b35344dca0a94231b2012321e7063c0a): perf score=1.000000
I20260812 06:19:32.441654 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushMRSOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.047s	user 0.036s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":249,"dirs.run_wall_time_us":1315,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1722,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:32.442423 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling LogGCOp(b35344dca0a94231b2012321e7063c0a): free 112239549 bytes of WAL
I20260812 06:19:32.442690 23496 log_reader.cc:385] T b35344dca0a94231b2012321e7063c0a: removed 11 log segments from log reader
I20260812 06:19:32.442739 23496 log.cc:1079] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/b35344dca0a94231b2012321e7063c0a/wal-000000027 (ops 128-132)
I20260812 06:19:32.442793 23496 log.cc:1079] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/b35344dca0a94231b2012321e7063c0a/wal-000000028 (ops 133-137)
I20260812 06:19:32.442842 23496 log.cc:1079] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/b35344dca0a94231b2012321e7063c0a/wal-000000029 (ops 138-142)
I20260812 06:19:32.442893 23496 log.cc:1079] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/b35344dca0a94231b2012321e7063c0a/wal-000000030 (ops 143-147)
I20260812 06:19:32.442940 23496 log.cc:1079] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/b35344dca0a94231b2012321e7063c0a/wal-000000031 (ops 148-152)
I20260812 06:19:32.443002 23496 log.cc:1079] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/b35344dca0a94231b2012321e7063c0a/wal-000000032 (ops 153-157)
I20260812 06:19:32.443054 23496 log.cc:1079] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/b35344dca0a94231b2012321e7063c0a/wal-000000033 (ops 158-162)
I20260812 06:19:32.443099 23496 log.cc:1079] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/b35344dca0a94231b2012321e7063c0a/wal-000000034 (ops 163-167)
I20260812 06:19:32.443140 23496 log.cc:1079] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/b35344dca0a94231b2012321e7063c0a/wal-000000035 (ops 168-172)
I20260812 06:19:32.443187 23496 log.cc:1079] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/b35344dca0a94231b2012321e7063c0a/wal-000000036 (ops 173-176)
I20260812 06:19:32.443230 23496 log.cc:1079] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: Deleting log segment in path: /tmp/dist-test-taskT95Asl/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515561743840-23147-0/minicluster-data/ts-0-root/wals/b35344dca0a94231b2012321e7063c0a/wal-000000037 (ops 177-181)
I20260812 06:19:32.471535 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: LogGCOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.029s	user 0.004s	sys 0.022s Metrics: {}
I20260812 06:19:32.472057 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling UndoDeltaBlockGCOp(b35344dca0a94231b2012321e7063c0a): 448 bytes on disk
I20260812 06:19:32.472534 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: UndoDeltaBlockGCOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4}
I20260812 06:19:32.473254 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=2.188937
I20260812 06:19:32.496951 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.024s	user 0.011s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6891,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:32.497552 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=2.188937
I20260812 06:19:32.513897 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6192,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:32.514669 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a): perf score=1.000000
I20260812 06:19:32.730239 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.215s	user 0.136s	sys 0.076s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836377,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":4448,"lbm_read_time_us":16529,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33289,"lbm_writes_lt_1ms":643,"mutex_wait_us":1249,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":58112,"thread_start_us":125,"threads_started":1,"update_count":3000}
I20260812 06:19:32.731211 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=14.095187
I20260812 06:19:32.791898 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.060s	user 0.033s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":28646,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:32.792474 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=2.188937
I20260812 06:19:32.814806 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.022s	user 0.007s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7171,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:32.815477 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a): perf score=1.000000
I20260812 06:19:32.926879 23147 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.113s	user 1.882s	sys 0.142s
I20260812 06:19:32.974854 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: MajorDeltaCompactionOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.159s	user 0.111s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":926,"lbm_read_time_us":11261,"lbm_reads_lt_1ms":560,"lbm_write_time_us":27675,"lbm_writes_lt_1ms":543,"mutex_wait_us":81,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":2500}
I20260812 06:19:32.975598 23576 maintenance_manager.cc:419] P 4d5d8512492f4673b87b7b00bb0d646c: Scheduling FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a): perf score=10.126437
I20260812 06:19:32.985992 23147 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.059s	user 0.002s	sys 0.000s
I20260812 06:19:32.986526 23147 tablet_server.cc:179] TabletServer@127.22.154.193:0 shutting down...
I20260812 06:19:33.014153 23496 maintenance_manager.cc:643] P 4d5d8512492f4673b87b7b00bb0d646c: FlushDeltaMemStoresOp(b35344dca0a94231b2012321e7063c0a) complete. Timing: real 0.038s	user 0.025s	sys 0.011s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16478,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:33.015394 23147 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:33.015656 23147 tablet_replica.cc:333] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c: stopping tablet replica
I20260812 06:19:33.015831 23147 raft_consensus.cc:2243] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:33.016031 23147 raft_consensus.cc:2272] T b35344dca0a94231b2012321e7063c0a P 4d5d8512492f4673b87b7b00bb0d646c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:33.033387 23147 tablet_server.cc:196] TabletServer@127.22.154.193:0 shutdown complete.
I20260812 06:19:33.036191 23147 master.cc:562] Master@127.22.154.254:39359 shutting down...
I20260812 06:19:33.039453 23147 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 096d548d13a344b8b3ff22fe8c043548 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:33.039636 23147 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 096d548d13a344b8b3ff22fe8c043548 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:33.039687 23147 tablet_replica.cc:333] T 00000000000000000000000000000000 P 096d548d13a344b8b3ff22fe8c043548: stopping tablet replica
I20260812 06:19:33.052421 23147 master.cc:584] Master@127.22.154.254:39359 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5563 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11393 ms total)

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