[==========] 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:17:42.569239 32175 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.31.107.254:34813
I20260812 06:17:42.570351 32175 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:17:42.570994 32175 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:42.577800 32183 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:17:42.577963 32181 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:17:42.577992 32175 server_base.cc:1061] running on GCE node
W20260812 06:17:42.578104 32180 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:17:42.579051 32175 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:42.579192 32175 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:17:42.579262 32175 hybrid_clock.cc:648] HybridClock initialized: now 1786515462579259 us; error 0 us; skew 500 ppm
I20260812 06:17:42.581219 32175 webserver.cc:533] Webserver started at http://127.31.107.254:44149/ using document root <none> and password file <none>
I20260812 06:17:42.581905 32175 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:42.582011 32175 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:42.582278 32175 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:42.584052 32175 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/master-0-root/instance:
uuid: "706f39405cbd482f951a31381eaf915f"
format_stamp: "Formatted at 2026-08-12 06:17:42 on dist-test-slave-0kls"
I20260812 06:17:42.587946 32175 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:17:42.590752 32190 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:17:42.591938 32175 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:42.592090 32175 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/master-0-root
uuid: "706f39405cbd482f951a31381eaf915f"
format_stamp: "Formatted at 2026-08-12 06:17:42 on dist-test-slave-0kls"
I20260812 06:17:42.592242 32175 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-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:17:42.617581 32175 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:42.618369 32175 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:17:42.618575 32175 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:42.626817 32175 rpc_server.cc:307] RPC server started. Bound to: 127.31.107.254:34813
I20260812 06:17:42.626832 32248 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.31.107.254:34813 every 8 connection(s)
I20260812 06:17:42.629184 32250 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:17:42.635195 32250 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 706f39405cbd482f951a31381eaf915f: Bootstrap starting.
I20260812 06:17:42.637626 32250 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 706f39405cbd482f951a31381eaf915f: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:42.638628 32250 log.cc:826] T 00000000000000000000000000000000 P 706f39405cbd482f951a31381eaf915f: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:42.640419 32250 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 706f39405cbd482f951a31381eaf915f: No bootstrap required, opened a new log
I20260812 06:17:42.643222 32250 raft_consensus.cc:359] T 00000000000000000000000000000000 P 706f39405cbd482f951a31381eaf915f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "706f39405cbd482f951a31381eaf915f" member_type: VOTER }
I20260812 06:17:42.643392 32250 raft_consensus.cc:385] T 00000000000000000000000000000000 P 706f39405cbd482f951a31381eaf915f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:42.643435 32250 raft_consensus.cc:740] T 00000000000000000000000000000000 P 706f39405cbd482f951a31381eaf915f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 706f39405cbd482f951a31381eaf915f, State: Initialized, Role: FOLLOWER
I20260812 06:17:42.644090 32250 consensus_queue.cc:260] T 00000000000000000000000000000000 P 706f39405cbd482f951a31381eaf915f [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: "706f39405cbd482f951a31381eaf915f" member_type: VOTER }
I20260812 06:17:42.644235 32250 raft_consensus.cc:399] T 00000000000000000000000000000000 P 706f39405cbd482f951a31381eaf915f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:42.644284 32250 raft_consensus.cc:493] T 00000000000000000000000000000000 P 706f39405cbd482f951a31381eaf915f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:42.644379 32250 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 706f39405cbd482f951a31381eaf915f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:42.645171 32250 raft_consensus.cc:515] T 00000000000000000000000000000000 P 706f39405cbd482f951a31381eaf915f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "706f39405cbd482f951a31381eaf915f" member_type: VOTER }
I20260812 06:17:42.645566 32250 leader_election.cc:304] T 00000000000000000000000000000000 P 706f39405cbd482f951a31381eaf915f [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: 706f39405cbd482f951a31381eaf915f; no voters: 
I20260812 06:17:42.645934 32250 leader_election.cc:290] T 00000000000000000000000000000000 P 706f39405cbd482f951a31381eaf915f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:42.646083 32253 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 706f39405cbd482f951a31381eaf915f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:42.646414 32253 raft_consensus.cc:697] T 00000000000000000000000000000000 P 706f39405cbd482f951a31381eaf915f [term 1 LEADER]: Becoming Leader. State: Replica: 706f39405cbd482f951a31381eaf915f, State: Running, Role: LEADER
I20260812 06:17:42.646839 32253 consensus_queue.cc:237] T 00000000000000000000000000000000 P 706f39405cbd482f951a31381eaf915f [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: "706f39405cbd482f951a31381eaf915f" member_type: VOTER }
I20260812 06:17:42.647020 32250 sys_catalog.cc:565] T 00000000000000000000000000000000 P 706f39405cbd482f951a31381eaf915f [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:42.648852 32255 sys_catalog.cc:455] T 00000000000000000000000000000000 P 706f39405cbd482f951a31381eaf915f [sys.catalog]: SysCatalogTable state changed. Reason: New leader 706f39405cbd482f951a31381eaf915f. Latest consensus state: current_term: 1 leader_uuid: "706f39405cbd482f951a31381eaf915f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "706f39405cbd482f951a31381eaf915f" member_type: VOTER } }
I20260812 06:17:42.648976 32255 sys_catalog.cc:458] T 00000000000000000000000000000000 P 706f39405cbd482f951a31381eaf915f [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:42.649243 32254 sys_catalog.cc:455] T 00000000000000000000000000000000 P 706f39405cbd482f951a31381eaf915f [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "706f39405cbd482f951a31381eaf915f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "706f39405cbd482f951a31381eaf915f" member_type: VOTER } }
I20260812 06:17:42.649317 32254 sys_catalog.cc:458] T 00000000000000000000000000000000 P 706f39405cbd482f951a31381eaf915f [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:42.649380 32175 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:42.649317 32267 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:42.651849 32267 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:42.657021 32267 catalog_manager.cc:1383] Generated new cluster ID: bc4d4138839c42bfb3ad4e872bedb775
I20260812 06:17:42.657111 32267 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:42.679442 32267 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:42.680406 32267 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:42.691648 32267 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 706f39405cbd482f951a31381eaf915f: Generated new TSK 0
I20260812 06:17:42.692377 32267 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:42.714517 32175 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:42.717631 32277 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:17:42.717625 32273 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:17:42.717744 32275 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:17:42.718037 32175 server_base.cc:1061] running on GCE node
I20260812 06:17:42.718216 32175 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:42.718263 32175 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:17:42.718286 32175 hybrid_clock.cc:648] HybridClock initialized: now 1786515462718285 us; error 0 us; skew 500 ppm
I20260812 06:17:42.719270 32175 webserver.cc:533] Webserver started at http://127.31.107.193:42595/ using document root <none> and password file <none>
I20260812 06:17:42.719445 32175 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:42.719506 32175 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:42.719596 32175 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:42.720088 32175 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root/instance:
uuid: "969b1f9a014a4169966bec9e48a80ea1"
format_stamp: "Formatted at 2026-08-12 06:17:42 on dist-test-slave-0kls"
I20260812 06:17:42.722023 32175 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:42.723120 32282 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:17:42.723428 32175 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:42.723492 32175 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root
uuid: "969b1f9a014a4169966bec9e48a80ea1"
format_stamp: "Formatted at 2026-08-12 06:17:42 on dist-test-slave-0kls"
I20260812 06:17:42.723548 32175 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-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:17:42.751469 32175 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:42.752133 32175 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:42.752700 32175 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:42.753582 32175 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:42.753635 32175 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:42.753708 32175 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:42.753772 32175 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:42.760782 32175 rpc_server.cc:307] RPC server started. Bound to: 127.31.107.193:42041
I20260812 06:17:42.760818 32360 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.31.107.193:42041 every 8 connection(s)
I20260812 06:17:42.773608 32361 heartbeater.cc:344] Connected to a master server at 127.31.107.254:34813
I20260812 06:17:42.773938 32361 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:42.774405 32361 heartbeater.cc:507] Master 127.31.107.254:34813 requested a full tablet report, sending...
I20260812 06:17:42.776013 32211 ts_manager.cc:194] Registered new tserver with Master: 969b1f9a014a4169966bec9e48a80ea1 (127.31.107.193:42041)
I20260812 06:17:42.776080 32175 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.014651601s
I20260812 06:17:42.777514 32211 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:33424
I20260812 06:17:42.786597 32211 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:33434:
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:17:42.800890 32315 tablet_service.cc:1511] Processing CreateTablet for tablet e00b1be40b86443c93e82a3786b5d274 (DEFAULT_TABLE table=heavy-update-compaction-test [id=3f950a1ec01e4aa3ab626d38dddeb579]), partition=
I20260812 06:17:42.801429 32315 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet e00b1be40b86443c93e82a3786b5d274. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:42.803948 32374 tablet_bootstrap.cc:492] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Bootstrap starting.
I20260812 06:17:42.805506 32374 tablet_bootstrap.cc:654] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:42.806962 32374 tablet_bootstrap.cc:492] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: No bootstrap required, opened a new log
I20260812 06:17:42.807083 32374 ts_tablet_manager.cc:1403] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Time spent bootstrapping tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:42.807680 32374 raft_consensus.cc:359] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "969b1f9a014a4169966bec9e48a80ea1" member_type: VOTER last_known_addr { host: "127.31.107.193" port: 42041 } }
I20260812 06:17:42.807817 32374 raft_consensus.cc:385] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:42.807866 32374 raft_consensus.cc:740] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 969b1f9a014a4169966bec9e48a80ea1, State: Initialized, Role: FOLLOWER
I20260812 06:17:42.808014 32374 consensus_queue.cc:260] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1 [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: "969b1f9a014a4169966bec9e48a80ea1" member_type: VOTER last_known_addr { host: "127.31.107.193" port: 42041 } }
I20260812 06:17:42.808122 32374 raft_consensus.cc:399] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:42.808183 32374 raft_consensus.cc:493] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:42.808238 32374 raft_consensus.cc:3060] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:42.809253 32374 raft_consensus.cc:515] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "969b1f9a014a4169966bec9e48a80ea1" member_type: VOTER last_known_addr { host: "127.31.107.193" port: 42041 } }
I20260812 06:17:42.809394 32374 leader_election.cc:304] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1 [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: 969b1f9a014a4169966bec9e48a80ea1; no voters: 
I20260812 06:17:42.809612 32374 leader_election.cc:290] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:42.809757 32376 raft_consensus.cc:2804] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:42.810014 32376 raft_consensus.cc:697] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1 [term 1 LEADER]: Becoming Leader. State: Replica: 969b1f9a014a4169966bec9e48a80ea1, State: Running, Role: LEADER
I20260812 06:17:42.810035 32374 ts_tablet_manager.cc:1434] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:42.810405 32361 heartbeater.cc:499] Master 127.31.107.254:34813 was elected leader, sending a full tablet report...
I20260812 06:17:42.810485 32376 consensus_queue.cc:237] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1 [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: "969b1f9a014a4169966bec9e48a80ea1" member_type: VOTER last_known_addr { host: "127.31.107.193" port: 42041 } }
I20260812 06:17:42.813366 32211 catalog_manager.cc:5719] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1 reported cstate change: term changed from 0 to 1, leader changed from <none> to 969b1f9a014a4169966bec9e48a80ea1 (127.31.107.193). New cstate: current_term: 1 leader_uuid: "969b1f9a014a4169966bec9e48a80ea1" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "969b1f9a014a4169966bec9e48a80ea1" member_type: VOTER last_known_addr { host: "127.31.107.193" port: 42041 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:42.876525 32175 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.021s	sys 0.003s
I20260812 06:17:43.012202 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushMRSOp(e00b1be40b86443c93e82a3786b5d274): perf score=15.086190
I20260812 06:17:43.170410 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushMRSOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.158s	user 0.132s	sys 0.024s Metrics: {"bytes_written":8615325,"cfile_init":1,"compiler_manager_pool.queue_time_us":404,"delete_count":0,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":215,"dirs.run_wall_time_us":914,"drs_written":1,"lbm_read_time_us":116,"lbm_reads_lt_1ms":4,"lbm_write_time_us":34986,"lbm_writes_lt_1ms":667,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":124,"threads_started":1,"update_count":1050}
I20260812 06:17:43.171532 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling LogGCOp(e00b1be40b86443c93e82a3786b5d274): free 20743880 bytes of WAL
I20260812 06:17:43.171869 32287 log_reader.cc:385] T e00b1be40b86443c93e82a3786b5d274: removed 2 log segments from log reader
I20260812 06:17:43.171952 32287 log.cc:1079] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/e00b1be40b86443c93e82a3786b5d274/wal-000000001 (ops 1-6)
I20260812 06:17:43.172027 32287 log.cc:1079] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/e00b1be40b86443c93e82a3786b5d274/wal-000000002 (ops 7-11)
I20260812 06:17:43.176344 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: LogGCOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.005s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:43.176704 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=2.188937
I20260812 06:17:43.192905 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5583,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:43.193637 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling MajorDeltaCompactionOp(e00b1be40b86443c93e82a3786b5d274): perf score=1.000000
I20260812 06:17:43.320741 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: MajorDeltaCompactionOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.127s	user 0.104s	sys 0.012s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16569858,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":533,"lbm_read_time_us":5998,"lbm_reads_lt_1ms":368,"lbm_write_time_us":22551,"lbm_writes_lt_1ms":343,"mutex_wait_us":59,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":9728,"thread_start_us":312,"threads_started":5,"update_count":1500}
I20260812 06:17:43.321333 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling UndoDeltaBlockGCOp(e00b1be40b86443c93e82a3786b5d274): 16411393 bytes on disk
I20260812 06:17:43.321970 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: UndoDeltaBlockGCOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:17:43.322619 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=10.126437
I20260812 06:17:43.364953 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.042s	user 0.022s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16590,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:43.365432 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=2.188937
I20260812 06:17:43.376323 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3935,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:43.377010 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling MajorDeltaCompactionOp(e00b1be40b86443c93e82a3786b5d274): perf score=1.000000
I20260812 06:17:43.510402 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: MajorDeltaCompactionOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.133s	user 0.105s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":872,"lbm_read_time_us":8020,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27139,"lbm_writes_lt_1ms":443,"mutex_wait_us":100,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:17:43.511070 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=10.126437
I20260812 06:17:43.563148 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.052s	user 0.028s	sys 0.017s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16748,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:43.563746 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=2.188937
I20260812 06:17:43.574395 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.010s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4075,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:43.574909 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling MajorDeltaCompactionOp(e00b1be40b86443c93e82a3786b5d274): perf score=1.000000
I20260812 06:17:43.729279 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: MajorDeltaCompactionOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.154s	user 0.108s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":904,"lbm_read_time_us":11249,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25380,"lbm_writes_lt_1ms":443,"mutex_wait_us":292,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":74880,"update_count":2000}
I20260812 06:17:43.730089 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=10.126437
I20260812 06:17:43.780006 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.050s	user 0.033s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16933,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:43.780540 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=2.188937
I20260812 06:17:43.791886 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4112,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:43.792451 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling MajorDeltaCompactionOp(e00b1be40b86443c93e82a3786b5d274): perf score=1.000000
I20260812 06:17:43.914531 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: MajorDeltaCompactionOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.122s	user 0.090s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":301,"lbm_read_time_us":7854,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25520,"lbm_writes_lt_1ms":443,"mutex_wait_us":40,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":2000}
I20260812 06:17:43.915169 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=10.126437
I20260812 06:17:43.968113 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.053s	user 0.021s	sys 0.013s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16028,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:43.968755 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=2.188937
I20260812 06:17:43.980468 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4296,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:43.981164 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling MajorDeltaCompactionOp(e00b1be40b86443c93e82a3786b5d274): perf score=1.000000
I20260812 06:17:44.107033 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: MajorDeltaCompactionOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.126s	user 0.103s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":976,"lbm_read_time_us":9551,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23896,"lbm_writes_lt_1ms":443,"mutex_wait_us":349,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":2000}
I20260812 06:17:44.107743 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=10.126437
I20260812 06:17:44.160390 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.052s	user 0.030s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15152,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:44.161098 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=2.188937
I20260812 06:17:44.177677 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.016s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":6256,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:44.178242 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling MajorDeltaCompactionOp(e00b1be40b86443c93e82a3786b5d274): perf score=1.000000
I20260812 06:17:44.327168 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: MajorDeltaCompactionOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.149s	user 0.107s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":107,"lbm_read_time_us":10882,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22774,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:44.337237 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=10.126437
I20260812 06:17:44.376173 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.039s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14475,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:44.376914 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=2.188937
I20260812 06:17:44.396193 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.019s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7210,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:44.396862 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling MajorDeltaCompactionOp(e00b1be40b86443c93e82a3786b5d274): perf score=1.000000
I20260812 06:17:44.584923 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: MajorDeltaCompactionOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.188s	user 0.144s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":480,"lbm_read_time_us":13787,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29093,"lbm_writes_lt_1ms":443,"mutex_wait_us":82,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18688,"update_count":2000}
I20260812 06:17:44.585768 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=14.095187
I20260812 06:17:44.634132 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.048s	user 0.031s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21027,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:44.634656 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushMRSOp(e00b1be40b86443c93e82a3786b5d274): perf score=1.000000
I20260812 06:17:44.707646 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushMRSOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.073s	user 0.034s	sys 0.008s Metrics: {"bytes_written":1316413,"cfile_init":1,"dirs.queue_time_us":96,"dirs.run_cpu_time_us":224,"dirs.run_wall_time_us":1594,"drs_written":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2379,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:44.708490 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling LogGCOp(e00b1be40b86443c93e82a3786b5d274): free 124257238 bytes of WAL
I20260812 06:17:44.708750 32287 log_reader.cc:385] T e00b1be40b86443c93e82a3786b5d274: removed 12 log segments from log reader
I20260812 06:17:44.708814 32287 log.cc:1079] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/e00b1be40b86443c93e82a3786b5d274/wal-000000003 (ops 12-16)
I20260812 06:17:44.708873 32287 log.cc:1079] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/e00b1be40b86443c93e82a3786b5d274/wal-000000004 (ops 17-21)
I20260812 06:17:44.708917 32287 log.cc:1079] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/e00b1be40b86443c93e82a3786b5d274/wal-000000005 (ops 22-26)
I20260812 06:17:44.708959 32287 log.cc:1079] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/e00b1be40b86443c93e82a3786b5d274/wal-000000006 (ops 27-31)
I20260812 06:17:44.709002 32287 log.cc:1079] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/e00b1be40b86443c93e82a3786b5d274/wal-000000007 (ops 32-36)
I20260812 06:17:44.709043 32287 log.cc:1079] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/e00b1be40b86443c93e82a3786b5d274/wal-000000008 (ops 37-40)
I20260812 06:17:44.709095 32287 log.cc:1079] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/e00b1be40b86443c93e82a3786b5d274/wal-000000009 (ops 41-45)
I20260812 06:17:44.709128 32287 log.cc:1079] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/e00b1be40b86443c93e82a3786b5d274/wal-000000010 (ops 46-50)
I20260812 06:17:44.709172 32287 log.cc:1079] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/e00b1be40b86443c93e82a3786b5d274/wal-000000011 (ops 51-55)
I20260812 06:17:44.709213 32287 log.cc:1079] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/e00b1be40b86443c93e82a3786b5d274/wal-000000012 (ops 56-60)
I20260812 06:17:44.709254 32287 log.cc:1079] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/e00b1be40b86443c93e82a3786b5d274/wal-000000013 (ops 61-65)
I20260812 06:17:44.709292 32287 log.cc:1079] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/e00b1be40b86443c93e82a3786b5d274/wal-000000014 (ops 66-70)
I20260812 06:17:44.738225 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: LogGCOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.030s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:17:44.738736 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=7.149875
I20260812 06:17:44.774340 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.035s	user 0.025s	sys 0.010s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":14138,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:17:44.775048 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling LogGCOp(e00b1be40b86443c93e82a3786b5d274): free 8767118 bytes of WAL
I20260812 06:17:44.775386 32287 log_reader.cc:385] T e00b1be40b86443c93e82a3786b5d274: removed 1 log segments from log reader
I20260812 06:17:44.775462 32287 log.cc:1079] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/e00b1be40b86443c93e82a3786b5d274/wal-000000015 (ops 71-75)
I20260812 06:17:44.778106 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: LogGCOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.003s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:44.778616 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=2.188937
I20260812 06:17:44.801633 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.023s	user 0.009s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6276,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:44.802367 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=2.188937
I20260812 06:17:44.820704 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.018s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6722,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:44.821353 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling UndoDeltaBlockGCOp(e00b1be40b86443c93e82a3786b5d274): 493 bytes on disk
I20260812 06:17:44.821946 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: UndoDeltaBlockGCOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":92,"lbm_reads_lt_1ms":4}
I20260812 06:17:44.822577 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling MajorDeltaCompactionOp(e00b1be40b86443c93e82a3786b5d274): perf score=1.000000
I20260812 06:17:45.075834 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: MajorDeltaCompactionOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.253s	user 0.155s	sys 0.087s Metrics: {"cfile_cache_miss":834,"cfile_cache_miss_bytes":37082155,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1363,"lbm_read_time_us":16673,"lbm_reads_lt_1ms":874,"lbm_write_time_us":41317,"lbm_writes_lt_1ms":843,"mutex_wait_us":664,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":18048,"thread_start_us":89,"threads_started":1,"update_count":4000}
I20260812 06:17:45.076504 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=18.063937
I20260812 06:17:45.151075 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.074s	user 0.035s	sys 0.026s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":27749,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:45.151635 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=2.188937
I20260812 06:17:45.162890 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4093,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:45.163800 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling MajorDeltaCompactionOp(e00b1be40b86443c93e82a3786b5d274): perf score=1.000000
I20260812 06:17:45.376605 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: MajorDeltaCompactionOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.213s	user 0.144s	sys 0.068s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":491,"lbm_read_time_us":15211,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35726,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":3000}
I20260812 06:17:45.377403 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=14.095187
I20260812 06:17:45.444835 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.067s	user 0.040s	sys 0.008s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":22202,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:45.445400 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=2.188937
I20260812 06:17:45.456202 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4055,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:45.456688 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling MajorDeltaCompactionOp(e00b1be40b86443c93e82a3786b5d274): perf score=1.000000
I20260812 06:17:45.627138 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: MajorDeltaCompactionOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.170s	user 0.135s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":681,"lbm_read_time_us":10692,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28572,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:45.627902 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=14.095187
I20260812 06:17:45.690017 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.062s	user 0.022s	sys 0.039s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":30327,"lbm_writes_1-10_ms":4,"lbm_writes_lt_1ms":399,"reinsert_count":0,"update_count":2000}
I20260812 06:17:45.690668 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=2.188937
I20260812 06:17:45.704371 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5353,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:45.704986 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling MajorDeltaCompactionOp(e00b1be40b86443c93e82a3786b5d274): perf score=1.000000
I20260812 06:17:45.889978 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: MajorDeltaCompactionOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.185s	user 0.116s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1037,"lbm_read_time_us":12341,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29421,"lbm_writes_lt_1ms":543,"mutex_wait_us":236,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":36608,"update_count":2500}
I20260812 06:17:45.890658 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=14.095187
I20260812 06:17:45.963374 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.072s	user 0.044s	sys 0.024s Metrics: {"bytes_written":16409881,"delete_count":0,"lbm_write_time_us":26795,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:45.964177 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=2.188937
I20260812 06:17:45.977684 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.013s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5174,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:45.978246 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling MajorDeltaCompactionOp(e00b1be40b86443c93e82a3786b5d274): perf score=1.000000
I20260812 06:17:46.174042 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: MajorDeltaCompactionOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.196s	user 0.132s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774668,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1464,"lbm_read_time_us":14211,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32020,"lbm_writes_lt_1ms":543,"mutex_wait_us":1200,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:46.174873 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=11.118625
I20260812 06:17:46.213090 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.038s	user 0.035s	sys 0.000s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16744,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:46.213991 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=2.188937
I20260812 06:17:46.228266 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.014s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5251,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:46.229014 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushMRSOp(e00b1be40b86443c93e82a3786b5d274): perf score=1.000000
I20260812 06:17:46.258806 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushMRSOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.030s	user 0.024s	sys 0.005s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":161,"dirs.run_wall_time_us":1265,"drs_written":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1922,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:46.259617 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling LogGCOp(e00b1be40b86443c93e82a3786b5d274): free 112239266 bytes of WAL
I20260812 06:17:46.259920 32287 log_reader.cc:385] T e00b1be40b86443c93e82a3786b5d274: removed 11 log segments from log reader
I20260812 06:17:46.259986 32287 log.cc:1079] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/e00b1be40b86443c93e82a3786b5d274/wal-000000016 (ops 76-80)
I20260812 06:17:46.260028 32287 log.cc:1079] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/e00b1be40b86443c93e82a3786b5d274/wal-000000017 (ops 81-85)
I20260812 06:17:46.260066 32287 log.cc:1079] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/e00b1be40b86443c93e82a3786b5d274/wal-000000018 (ops 86-90)
I20260812 06:17:46.260092 32287 log.cc:1079] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/e00b1be40b86443c93e82a3786b5d274/wal-000000019 (ops 91-94)
I20260812 06:17:46.260123 32287 log.cc:1079] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/e00b1be40b86443c93e82a3786b5d274/wal-000000020 (ops 95-99)
I20260812 06:17:46.260154 32287 log.cc:1079] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/e00b1be40b86443c93e82a3786b5d274/wal-000000021 (ops 100-104)
I20260812 06:17:46.260183 32287 log.cc:1079] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/e00b1be40b86443c93e82a3786b5d274/wal-000000022 (ops 105-109)
I20260812 06:17:46.260212 32287 log.cc:1079] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/e00b1be40b86443c93e82a3786b5d274/wal-000000023 (ops 110-114)
I20260812 06:17:46.260245 32287 log.cc:1079] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/e00b1be40b86443c93e82a3786b5d274/wal-000000024 (ops 115-119)
I20260812 06:17:46.260278 32287 log.cc:1079] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/e00b1be40b86443c93e82a3786b5d274/wal-000000025 (ops 120-124)
I20260812 06:17:46.260313 32287 log.cc:1079] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/e00b1be40b86443c93e82a3786b5d274/wal-000000026 (ops 125-129)
I20260812 06:17:46.290022 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: LogGCOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.030s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:17:46.290594 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling UndoDeltaBlockGCOp(e00b1be40b86443c93e82a3786b5d274): 462 bytes on disk
I20260812 06:17:46.291142 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: UndoDeltaBlockGCOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:17:46.292479 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=3.181125
I20260812 06:17:46.313299 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.021s	user 0.006s	sys 0.010s Metrics: {"bytes_written":4348806,"delete_count":0,"lbm_write_time_us":6916,"lbm_writes_lt_1ms":109,"reinsert_count":0,"update_count":530}
I20260812 06:17:46.313831 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=2.188937
I20260812 06:17:46.324030 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3856508,"delete_count":0,"lbm_write_time_us":3635,"lbm_writes_lt_1ms":97,"reinsert_count":0,"update_count":470}
I20260812 06:17:46.324590 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling LogGCOp(e00b1be40b86443c93e82a3786b5d274): free 12018006 bytes of WAL
I20260812 06:17:46.324848 32287 log_reader.cc:385] T e00b1be40b86443c93e82a3786b5d274: removed 1 log segments from log reader
I20260812 06:17:46.324895 32287 log.cc:1079] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/e00b1be40b86443c93e82a3786b5d274/wal-000000027 (ops 130-134)
I20260812 06:17:46.328075 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: LogGCOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:46.328491 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling MajorDeltaCompactionOp(e00b1be40b86443c93e82a3786b5d274): perf score=1.000000
I20260812 06:17:46.531759 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: MajorDeltaCompactionOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.203s	user 0.142s	sys 0.060s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877326,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":818,"lbm_read_time_us":12995,"lbm_reads_lt_1ms":674,"lbm_write_time_us":37040,"lbm_writes_lt_1ms":643,"mutex_wait_us":371,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2560,"thread_start_us":80,"threads_started":1,"update_count":3000}
I20260812 06:17:46.533514 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=14.095187
I20260812 06:17:46.584865 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.051s	user 0.026s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21836,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:46.585464 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=2.188937
I20260812 06:17:46.596633 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4307,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:46.597138 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling MajorDeltaCompactionOp(e00b1be40b86443c93e82a3786b5d274): perf score=1.000000
I20260812 06:17:46.766976 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: MajorDeltaCompactionOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.170s	user 0.085s	sys 0.079s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":109,"lbm_read_time_us":12206,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27479,"lbm_writes_lt_1ms":543,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5504,"update_count":2500}
I20260812 06:17:46.767728 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=14.095187
I20260812 06:17:46.832719 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.065s	user 0.024s	sys 0.032s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21409,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:46.833333 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=2.188937
I20260812 06:17:46.844791 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4443,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:46.845438 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling MajorDeltaCompactionOp(e00b1be40b86443c93e82a3786b5d274): perf score=1.000000
I20260812 06:17:47.023514 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: MajorDeltaCompactionOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.178s	user 0.139s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":156,"lbm_read_time_us":13910,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31137,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:47.024233 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=10.126437
I20260812 06:17:47.063436 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.039s	user 0.024s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17267,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:47.064034 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=2.188937
I20260812 06:17:47.076476 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4813,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.077001 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling MajorDeltaCompactionOp(e00b1be40b86443c93e82a3786b5d274): perf score=1.000000
I20260812 06:17:47.232295 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: MajorDeltaCompactionOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.155s	user 0.109s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":342,"lbm_read_time_us":9897,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25635,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2000}
I20260812 06:17:47.233157 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=10.126437
I20260812 06:17:47.271528 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.038s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15129,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:47.272068 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=2.188937
I20260812 06:17:47.283843 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.012s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4264,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.284508 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling MajorDeltaCompactionOp(e00b1be40b86443c93e82a3786b5d274): perf score=1.000000
I20260812 06:17:47.409955 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: MajorDeltaCompactionOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.125s	user 0.109s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":334,"lbm_read_time_us":7673,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23941,"lbm_writes_lt_1ms":443,"mutex_wait_us":73,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:47.410655 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=10.126437
I20260812 06:17:47.457927 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.047s	user 0.031s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16781,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:47.458520 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=2.188937
I20260812 06:17:47.472707 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5675,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.473274 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling MajorDeltaCompactionOp(e00b1be40b86443c93e82a3786b5d274): perf score=1.000000
I20260812 06:17:47.597085 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: MajorDeltaCompactionOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.124s	user 0.084s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":532,"lbm_read_time_us":9973,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23321,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":2000}
I20260812 06:17:47.597784 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=10.126437
I20260812 06:17:47.643558 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.046s	user 0.032s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15995,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:47.644078 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=2.188937
I20260812 06:17:47.655299 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4146,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.655853 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling MajorDeltaCompactionOp(e00b1be40b86443c93e82a3786b5d274): perf score=1.000000
I20260812 06:17:47.801276 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: MajorDeltaCompactionOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.145s	user 0.117s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":175,"lbm_read_time_us":11143,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24349,"lbm_writes_lt_1ms":443,"mutex_wait_us":41,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2000}
I20260812 06:17:47.802075 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=10.126437
I20260812 06:17:47.845176 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.043s	user 0.030s	sys 0.009s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18824,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:47.845881 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=2.188937
I20260812 06:17:47.857890 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4081,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.858610 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushMRSOp(e00b1be40b86443c93e82a3786b5d274): perf score=1.000000
I20260812 06:17:47.891522 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushMRSOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.033s	user 0.030s	sys 0.001s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":221,"dirs.run_wall_time_us":1571,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1518,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:47.892257 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling LogGCOp(e00b1be40b86443c93e82a3786b5d274): free 124710569 bytes of WAL
I20260812 06:17:47.892498 32287 log_reader.cc:385] T e00b1be40b86443c93e82a3786b5d274: removed 12 log segments from log reader
I20260812 06:17:47.892541 32287 log.cc:1079] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/e00b1be40b86443c93e82a3786b5d274/wal-000000028 (ops 135-139)
I20260812 06:17:47.892571 32287 log.cc:1079] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/e00b1be40b86443c93e82a3786b5d274/wal-000000029 (ops 140-144)
I20260812 06:17:47.892644 32287 log.cc:1079] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/e00b1be40b86443c93e82a3786b5d274/wal-000000030 (ops 145-149)
I20260812 06:17:47.892678 32287 log.cc:1079] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/e00b1be40b86443c93e82a3786b5d274/wal-000000031 (ops 150-154)
I20260812 06:17:47.892722 32287 log.cc:1079] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/e00b1be40b86443c93e82a3786b5d274/wal-000000032 (ops 155-159)
I20260812 06:17:47.892752 32287 log.cc:1079] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/e00b1be40b86443c93e82a3786b5d274/wal-000000033 (ops 160-164)
I20260812 06:17:47.892788 32287 log.cc:1079] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/e00b1be40b86443c93e82a3786b5d274/wal-000000034 (ops 165-169)
I20260812 06:17:47.892830 32287 log.cc:1079] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/e00b1be40b86443c93e82a3786b5d274/wal-000000035 (ops 170-174)
I20260812 06:17:47.892872 32287 log.cc:1079] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/e00b1be40b86443c93e82a3786b5d274/wal-000000036 (ops 175-179)
I20260812 06:17:47.892913 32287 log.cc:1079] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/e00b1be40b86443c93e82a3786b5d274/wal-000000037 (ops 180-184)
I20260812 06:17:47.892953 32287 log.cc:1079] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/e00b1be40b86443c93e82a3786b5d274/wal-000000038 (ops 185-189)
I20260812 06:17:47.892992 32287 log.cc:1079] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/e00b1be40b86443c93e82a3786b5d274/wal-000000039 (ops 190-194)
I20260812 06:17:47.920940 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: LogGCOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:17:47.921407 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=5.165500
I20260812 06:17:47.952631 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.031s	user 0.017s	sys 0.011s Metrics: {"bytes_written":6441039,"delete_count":0,"lbm_write_time_us":8011,"lbm_writes_lt_1ms":160,"reinsert_count":0,"spinlock_wait_cycles":384,"update_count":785}
I20260812 06:17:47.953356 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=1.000000
I20260812 06:17:47.959687 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.006s	user 0.005s	sys 0.000s Metrics: {"bytes_written":1764227,"delete_count":0,"lbm_write_time_us":1846,"lbm_writes_lt_1ms":46,"reinsert_count":0,"update_count":215}
I20260812 06:17:47.960209 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling MajorDeltaCompactionOp(e00b1be40b86443c93e82a3786b5d274): perf score=1.000000
I20260812 06:17:48.067202 32175 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.191s	user 1.874s	sys 0.204s
I20260812 06:17:48.148900 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: MajorDeltaCompactionOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.188s	user 0.099s	sys 0.087s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877283,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":286,"lbm_read_time_us":14645,"lbm_reads_lt_1ms":670,"lbm_write_time_us":30680,"lbm_writes_lt_1ms":643,"mutex_wait_us":83,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":89,"threads_started":1,"update_count":3000}
I20260812 06:17:48.149729 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling UndoDeltaBlockGCOp(e00b1be40b86443c93e82a3786b5d274): 482 bytes on disk
I20260812 06:17:48.150360 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: UndoDeltaBlockGCOp(e00b1be40b86443c93e82a3786b5d274) 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:17:48.151206 32362 maintenance_manager.cc:419] P 969b1f9a014a4169966bec9e48a80ea1: Scheduling FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274): perf score=6.157687
I20260812 06:17:48.152760 32175 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.085s	user 0.001s	sys 0.000s
I20260812 06:17:48.153417 32175 tablet_server.cc:179] TabletServer@127.31.107.193:0 shutting down...
I20260812 06:17:48.176086 32287 maintenance_manager.cc:643] P 969b1f9a014a4169966bec9e48a80ea1: FlushDeltaMemStoresOp(e00b1be40b86443c93e82a3786b5d274) complete. Timing: real 0.025s	user 0.012s	sys 0.010s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":10177,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:48.176767 32175 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:48.177202 32175 tablet_replica.cc:333] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1: stopping tablet replica
I20260812 06:17:48.177467 32175 raft_consensus.cc:2243] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:48.177732 32175 raft_consensus.cc:2272] T e00b1be40b86443c93e82a3786b5d274 P 969b1f9a014a4169966bec9e48a80ea1 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:48.194137 32175 tablet_server.cc:196] TabletServer@127.31.107.193:0 shutdown complete.
I20260812 06:17:48.199220 32175 master.cc:562] Master@127.31.107.254:34813 shutting down...
I20260812 06:17:48.203105 32175 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 706f39405cbd482f951a31381eaf915f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:48.203330 32175 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 706f39405cbd482f951a31381eaf915f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:48.203425 32175 tablet_replica.cc:333] T 00000000000000000000000000000000 P 706f39405cbd482f951a31381eaf915f: stopping tablet replica
I20260812 06:17:48.216043 32175 master.cc:584] Master@127.31.107.254:34813 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5738 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:48.320035 32175 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.31.107.254:44881
I20260812 06:17:48.320533 32175 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:48.322985 32394 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:17:48.323002 32397 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:17:48.323071 32175 server_base.cc:1061] running on GCE node
W20260812 06:17:48.323012 32395 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:17:48.323397 32175 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:48.323441 32175 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:17:48.323457 32175 hybrid_clock.cc:648] HybridClock initialized: now 1786515468323457 us; error 0 us; skew 500 ppm
I20260812 06:17:48.324306 32175 webserver.cc:533] Webserver started at http://127.31.107.254:39513/ using document root <none> and password file <none>
I20260812 06:17:48.324451 32175 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:48.324496 32175 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:48.324556 32175 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:48.324911 32175 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/master-0-root/instance:
uuid: "0fd37d6be3124236b667eb960217f9d1"
format_stamp: "Formatted at 2026-08-12 06:17:48 on dist-test-slave-0kls"
I20260812 06:17:48.326543 32175 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:48.327574 32402 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:17:48.327840 32175 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:48.327912 32175 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/master-0-root
uuid: "0fd37d6be3124236b667eb960217f9d1"
format_stamp: "Formatted at 2026-08-12 06:17:48 on dist-test-slave-0kls"
I20260812 06:17:48.327991 32175 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-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:17:48.347339 32175 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:48.347757 32175 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:48.352830 32175 rpc_server.cc:307] RPC server started. Bound to: 127.31.107.254:44881
I20260812 06:17:48.354884 32461 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.31.107.254:44881 every 8 connection(s)
I20260812 06:17:48.359323 32462 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:17:48.362260 32462 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0fd37d6be3124236b667eb960217f9d1: Bootstrap starting.
I20260812 06:17:48.363152 32462 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 0fd37d6be3124236b667eb960217f9d1: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:48.364275 32462 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0fd37d6be3124236b667eb960217f9d1: No bootstrap required, opened a new log
I20260812 06:17:48.364745 32462 raft_consensus.cc:359] T 00000000000000000000000000000000 P 0fd37d6be3124236b667eb960217f9d1 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0fd37d6be3124236b667eb960217f9d1" member_type: VOTER }
I20260812 06:17:48.364859 32462 raft_consensus.cc:385] T 00000000000000000000000000000000 P 0fd37d6be3124236b667eb960217f9d1 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:48.364923 32462 raft_consensus.cc:740] T 00000000000000000000000000000000 P 0fd37d6be3124236b667eb960217f9d1 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0fd37d6be3124236b667eb960217f9d1, State: Initialized, Role: FOLLOWER
I20260812 06:17:48.365103 32462 consensus_queue.cc:260] T 00000000000000000000000000000000 P 0fd37d6be3124236b667eb960217f9d1 [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: "0fd37d6be3124236b667eb960217f9d1" member_type: VOTER }
I20260812 06:17:48.365199 32462 raft_consensus.cc:399] T 00000000000000000000000000000000 P 0fd37d6be3124236b667eb960217f9d1 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:48.365244 32462 raft_consensus.cc:493] T 00000000000000000000000000000000 P 0fd37d6be3124236b667eb960217f9d1 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:48.365301 32462 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 0fd37d6be3124236b667eb960217f9d1 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:48.366150 32462 raft_consensus.cc:515] T 00000000000000000000000000000000 P 0fd37d6be3124236b667eb960217f9d1 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0fd37d6be3124236b667eb960217f9d1" member_type: VOTER }
I20260812 06:17:48.366317 32462 leader_election.cc:304] T 00000000000000000000000000000000 P 0fd37d6be3124236b667eb960217f9d1 [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: 0fd37d6be3124236b667eb960217f9d1; no voters: 
I20260812 06:17:48.366540 32462 leader_election.cc:290] T 00000000000000000000000000000000 P 0fd37d6be3124236b667eb960217f9d1 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:48.366669 32466 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 0fd37d6be3124236b667eb960217f9d1 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:48.366891 32466 raft_consensus.cc:697] T 00000000000000000000000000000000 P 0fd37d6be3124236b667eb960217f9d1 [term 1 LEADER]: Becoming Leader. State: Replica: 0fd37d6be3124236b667eb960217f9d1, State: Running, Role: LEADER
I20260812 06:17:48.367050 32466 consensus_queue.cc:237] T 00000000000000000000000000000000 P 0fd37d6be3124236b667eb960217f9d1 [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: "0fd37d6be3124236b667eb960217f9d1" member_type: VOTER }
I20260812 06:17:48.367120 32462 sys_catalog.cc:565] T 00000000000000000000000000000000 P 0fd37d6be3124236b667eb960217f9d1 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:48.367578 32467 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0fd37d6be3124236b667eb960217f9d1 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "0fd37d6be3124236b667eb960217f9d1" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0fd37d6be3124236b667eb960217f9d1" member_type: VOTER } }
I20260812 06:17:48.367601 32468 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0fd37d6be3124236b667eb960217f9d1 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 0fd37d6be3124236b667eb960217f9d1. Latest consensus state: current_term: 1 leader_uuid: "0fd37d6be3124236b667eb960217f9d1" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0fd37d6be3124236b667eb960217f9d1" member_type: VOTER } }
I20260812 06:17:48.367674 32467 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0fd37d6be3124236b667eb960217f9d1 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:48.367692 32468 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0fd37d6be3124236b667eb960217f9d1 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:48.367937 32470 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:48.368798 32470 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:48.369076 32175 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:48.370959 32470 catalog_manager.cc:1383] Generated new cluster ID: 8da41b47074e459492ea5b1b58c0ed67
I20260812 06:17:48.371025 32470 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:48.381074 32470 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:48.381727 32470 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:48.395934 32470 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 0fd37d6be3124236b667eb960217f9d1: Generated new TSK 0
I20260812 06:17:48.396194 32470 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:48.401691 32175 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:48.403930 32487 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:17:48.403983 32490 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:17:48.404019 32488 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:17:48.404295 32175 server_base.cc:1061] running on GCE node
I20260812 06:17:48.404453 32175 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:48.404490 32175 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:17:48.404506 32175 hybrid_clock.cc:648] HybridClock initialized: now 1786515468404506 us; error 0 us; skew 500 ppm
I20260812 06:17:48.405382 32175 webserver.cc:533] Webserver started at http://127.31.107.193:33405/ using document root <none> and password file <none>
I20260812 06:17:48.405531 32175 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:48.405579 32175 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:48.405642 32175 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:48.406097 32175 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root/instance:
uuid: "b50740b6d34943d69077d44584907107"
format_stamp: "Formatted at 2026-08-12 06:17:48 on dist-test-slave-0kls"
I20260812 06:17:48.407658 32175 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:17:48.408651 32496 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:17:48.408921 32175 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:48.408993 32175 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root
uuid: "b50740b6d34943d69077d44584907107"
format_stamp: "Formatted at 2026-08-12 06:17:48 on dist-test-slave-0kls"
I20260812 06:17:48.409056 32175 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-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:17:48.424050 32175 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:48.424477 32175 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:48.424739 32175 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:48.425271 32175 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:48.425313 32175 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:48.425380 32175 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:48.425418 32175 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:48.430229 32175 rpc_server.cc:307] RPC server started. Bound to: 127.31.107.193:40955
I20260812 06:17:48.430450 32569 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.31.107.193:40955 every 8 connection(s)
I20260812 06:17:48.440148 32570 heartbeater.cc:344] Connected to a master server at 127.31.107.254:44881
I20260812 06:17:48.440292 32570 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:48.440528 32570 heartbeater.cc:507] Master 127.31.107.254:44881 requested a full tablet report, sending...
I20260812 06:17:48.441247 32421 ts_manager.cc:194] Registered new tserver with Master: b50740b6d34943d69077d44584907107 (127.31.107.193:40955)
I20260812 06:17:48.441869 32175 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01107071s
I20260812 06:17:48.442200 32421 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:37656
I20260812 06:17:48.449769 32421 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:37662:
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:17:48.460574 32532 tablet_service.cc:1511] Processing CreateTablet for tablet 22f3168aa0a7423bab9e15fa2b36cc79 (DEFAULT_TABLE table=heavy-update-compaction-test [id=a3418681bcf24c6dabbfec5bc3cf6feb]), partition=
I20260812 06:17:48.460914 32532 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 22f3168aa0a7423bab9e15fa2b36cc79. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:48.463384 32582 tablet_bootstrap.cc:492] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Bootstrap starting.
I20260812 06:17:48.464306 32582 tablet_bootstrap.cc:654] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:48.465552 32582 tablet_bootstrap.cc:492] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: No bootstrap required, opened a new log
I20260812 06:17:48.465672 32582 ts_tablet_manager.cc:1403] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:48.466295 32582 raft_consensus.cc:359] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b50740b6d34943d69077d44584907107" member_type: VOTER last_known_addr { host: "127.31.107.193" port: 40955 } }
I20260812 06:17:48.466423 32582 raft_consensus.cc:385] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:48.466471 32582 raft_consensus.cc:740] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b50740b6d34943d69077d44584907107, State: Initialized, Role: FOLLOWER
I20260812 06:17:48.466630 32582 consensus_queue.cc:260] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107 [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: "b50740b6d34943d69077d44584907107" member_type: VOTER last_known_addr { host: "127.31.107.193" port: 40955 } }
I20260812 06:17:48.466724 32582 raft_consensus.cc:399] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:48.466770 32582 raft_consensus.cc:493] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:48.466825 32582 raft_consensus.cc:3060] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:48.467629 32582 raft_consensus.cc:515] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b50740b6d34943d69077d44584907107" member_type: VOTER last_known_addr { host: "127.31.107.193" port: 40955 } }
I20260812 06:17:48.467795 32582 leader_election.cc:304] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107 [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: b50740b6d34943d69077d44584907107; no voters: 
I20260812 06:17:48.468032 32582 leader_election.cc:290] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:48.468212 32584 raft_consensus.cc:2804] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:48.468406 32570 heartbeater.cc:499] Master 127.31.107.254:44881 was elected leader, sending a full tablet report...
I20260812 06:17:48.468497 32582 ts_tablet_manager.cc:1434] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:48.468500 32584 raft_consensus.cc:697] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107 [term 1 LEADER]: Becoming Leader. State: Replica: b50740b6d34943d69077d44584907107, State: Running, Role: LEADER
I20260812 06:17:48.468780 32584 consensus_queue.cc:237] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107 [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: "b50740b6d34943d69077d44584907107" member_type: VOTER last_known_addr { host: "127.31.107.193" port: 40955 } }
I20260812 06:17:48.470505 32420 catalog_manager.cc:5719] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107 reported cstate change: term changed from 0 to 1, leader changed from <none> to b50740b6d34943d69077d44584907107 (127.31.107.193). New cstate: current_term: 1 leader_uuid: "b50740b6d34943d69077d44584907107" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b50740b6d34943d69077d44584907107" member_type: VOTER last_known_addr { host: "127.31.107.193" port: 40955 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:48.531745 32175 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.015s	sys 0.008s
I20260812 06:17:48.681433 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushMRSOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=19.054940
I20260812 06:17:48.867508 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushMRSOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.186s	user 0.136s	sys 0.047s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":234,"dirs.run_wall_time_us":892,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41698,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:17:48.868443 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling LogGCOp(22f3168aa0a7423bab9e15fa2b36cc79): free 20743831 bytes of WAL
I20260812 06:17:48.868798 32502 log_reader.cc:385] T 22f3168aa0a7423bab9e15fa2b36cc79: removed 2 log segments from log reader
I20260812 06:17:48.868878 32502 log.cc:1079] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/22f3168aa0a7423bab9e15fa2b36cc79/wal-000000001 (ops 1-6)
I20260812 06:17:48.868940 32502 log.cc:1079] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/22f3168aa0a7423bab9e15fa2b36cc79/wal-000000002 (ops 7-11)
I20260812 06:17:48.873425 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: LogGCOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.005s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:48.873970 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling UndoDeltaBlockGCOp(22f3168aa0a7423bab9e15fa2b36cc79): 16411391 bytes on disk
I20260812 06:17:48.874490 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: UndoDeltaBlockGCOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4}
I20260812 06:17:48.874961 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=2.188937
I20260812 06:17:48.890398 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5546,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:48.891131 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling MajorDeltaCompactionOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=1.000000
I20260812 06:17:49.048377 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: MajorDeltaCompactionOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.157s	user 0.105s	sys 0.051s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":920,"lbm_read_time_us":10071,"lbm_reads_lt_1ms":460,"lbm_write_time_us":26820,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3072,"thread_start_us":357,"threads_started":5,"update_count":2000}
I20260812 06:17:49.048947 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=10.126437
I20260812 06:17:49.089696 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.041s	user 0.030s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18169,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:49.090384 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=2.188937
I20260812 06:17:49.109468 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.019s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5633,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:49.110098 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling MajorDeltaCompactionOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=1.000000
I20260812 06:17:49.268150 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: MajorDeltaCompactionOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.158s	user 0.125s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":241,"lbm_read_time_us":9933,"lbm_reads_lt_1ms":464,"lbm_write_time_us":29308,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:17:49.268776 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=10.126437
I20260812 06:17:49.302033 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.033s	user 0.017s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14307,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:49.302742 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=2.188937
I20260812 06:17:49.319029 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.016s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6488,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:49.319526 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling MajorDeltaCompactionOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=1.000000
I20260812 06:17:49.446818 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: MajorDeltaCompactionOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.127s	user 0.095s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":827,"lbm_read_time_us":8494,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23408,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17536,"update_count":2000}
I20260812 06:17:49.447482 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=10.126437
I20260812 06:17:49.497280 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.050s	user 0.011s	sys 0.027s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16871,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:49.497897 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=2.188937
I20260812 06:17:49.509064 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4044,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:49.509930 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling MajorDeltaCompactionOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=1.000000
I20260812 06:17:49.635763 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: MajorDeltaCompactionOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.126s	user 0.108s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":281,"lbm_read_time_us":9746,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23532,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":112640,"update_count":2000}
I20260812 06:17:49.636370 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=10.126437
I20260812 06:17:49.683485 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.047s	user 0.023s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13017,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:49.684700 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=1.000000
I20260812 06:17:49.697386 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.012s	user 0.006s	sys 0.000s Metrics: {"bytes_written":1312955,"delete_count":0,"lbm_write_time_us":2289,"lbm_writes_lt_1ms":35,"reinsert_count":0,"update_count":160}
I20260812 06:17:49.697948 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=1.196750
I20260812 06:17:49.706097 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.008s	user 0.003s	sys 0.005s Metrics: {"bytes_written":2789855,"delete_count":0,"lbm_write_time_us":2817,"lbm_writes_lt_1ms":71,"reinsert_count":0,"update_count":340}
I20260812 06:17:49.706748 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling MajorDeltaCompactionOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=1.000000
I20260812 06:17:49.863754 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: MajorDeltaCompactionOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.157s	user 0.076s	sys 0.080s Metrics: {"cfile_cache_miss":433,"cfile_cache_miss_bytes":20672301,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":174,"lbm_read_time_us":10917,"lbm_reads_lt_1ms":473,"lbm_write_time_us":26382,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13440,"update_count":2000}
I20260812 06:17:49.864379 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=10.126437
I20260812 06:17:49.914925 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.050s	user 0.026s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17082,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:49.915467 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=2.188937
I20260812 06:17:49.926534 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4145,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:49.927320 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling MajorDeltaCompactionOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=1.000000
I20260812 06:17:50.066455 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: MajorDeltaCompactionOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.139s	user 0.099s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":9248,"lbm_read_time_us":9355,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26967,"lbm_writes_lt_1ms":443,"mutex_wait_us":3174,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":22528,"update_count":2000}
I20260812 06:17:50.067162 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=10.126437
I20260812 06:17:50.117462 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.050s	user 0.020s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16916,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:50.118088 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=2.188937
I20260812 06:17:50.128908 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4047,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:50.129678 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushMRSOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=1.000000
I20260812 06:17:50.162799 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushMRSOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.033s	user 0.026s	sys 0.006s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":105,"dirs.run_cpu_time_us":284,"dirs.run_wall_time_us":1525,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2157,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:50.163399 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling LogGCOp(22f3168aa0a7423bab9e15fa2b36cc79): free 112239315 bytes of WAL
I20260812 06:17:50.163633 32502 log_reader.cc:385] T 22f3168aa0a7423bab9e15fa2b36cc79: removed 11 log segments from log reader
I20260812 06:17:50.163697 32502 log.cc:1079] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/22f3168aa0a7423bab9e15fa2b36cc79/wal-000000003 (ops 12-16)
I20260812 06:17:50.163754 32502 log.cc:1079] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/22f3168aa0a7423bab9e15fa2b36cc79/wal-000000004 (ops 17-21)
I20260812 06:17:50.163813 32502 log.cc:1079] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/22f3168aa0a7423bab9e15fa2b36cc79/wal-000000005 (ops 22-26)
I20260812 06:17:50.163856 32502 log.cc:1079] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/22f3168aa0a7423bab9e15fa2b36cc79/wal-000000006 (ops 27-31)
I20260812 06:17:50.163898 32502 log.cc:1079] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/22f3168aa0a7423bab9e15fa2b36cc79/wal-000000007 (ops 32-36)
I20260812 06:17:50.163937 32502 log.cc:1079] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/22f3168aa0a7423bab9e15fa2b36cc79/wal-000000008 (ops 37-40)
I20260812 06:17:50.163976 32502 log.cc:1079] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/22f3168aa0a7423bab9e15fa2b36cc79/wal-000000009 (ops 41-45)
I20260812 06:17:50.164013 32502 log.cc:1079] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/22f3168aa0a7423bab9e15fa2b36cc79/wal-000000010 (ops 46-50)
I20260812 06:17:50.164052 32502 log.cc:1079] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/22f3168aa0a7423bab9e15fa2b36cc79/wal-000000011 (ops 51-55)
I20260812 06:17:50.164090 32502 log.cc:1079] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/22f3168aa0a7423bab9e15fa2b36cc79/wal-000000012 (ops 56-60)
I20260812 06:17:50.164129 32502 log.cc:1079] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/22f3168aa0a7423bab9e15fa2b36cc79/wal-000000013 (ops 61-65)
I20260812 06:17:50.190219 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: LogGCOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:50.190649 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=2.188937
I20260812 06:17:50.212972 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.022s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5614,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:50.213529 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling UndoDeltaBlockGCOp(22f3168aa0a7423bab9e15fa2b36cc79): 447 bytes on disk
I20260812 06:17:50.214042 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: UndoDeltaBlockGCOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":123,"lbm_reads_lt_1ms":4}
I20260812 06:17:50.214506 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=2.188937
I20260812 06:17:50.225556 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3974,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:50.226405 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling MajorDeltaCompactionOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=1.000000
I20260812 06:17:50.396799 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: MajorDeltaCompactionOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.170s	user 0.093s	sys 0.075s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877338,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":641,"lbm_read_time_us":13322,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34271,"lbm_writes_lt_1ms":643,"mutex_wait_us":242,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14208,"thread_start_us":131,"threads_started":1,"update_count":3000}
I20260812 06:17:50.397439 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=10.126437
I20260812 06:17:50.433849 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.036s	user 0.018s	sys 0.014s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16803,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:50.435482 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=2.188937
I20260812 06:17:50.448633 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.013s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4315,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:50.449333 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling MajorDeltaCompactionOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=1.000000
I20260812 06:17:50.584739 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: MajorDeltaCompactionOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.135s	user 0.105s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":481,"lbm_read_time_us":10065,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25530,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":21760,"update_count":2000}
I20260812 06:17:50.585415 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=10.126437
I20260812 06:17:50.641259 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.056s	user 0.030s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20804,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:17:50.641940 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=2.188937
I20260812 06:17:50.653000 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.011s	user 0.009s	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:17:50.653545 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling MajorDeltaCompactionOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=1.000000
I20260812 06:17:50.799729 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: MajorDeltaCompactionOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.146s	user 0.118s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":262,"lbm_read_time_us":11611,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23360,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":2000}
I20260812 06:17:50.801627 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=10.126437
I20260812 06:17:50.839318 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.037s	user 0.017s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14534,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:50.839936 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=2.188937
I20260812 06:17:50.850953 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4274,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:50.851409 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling MajorDeltaCompactionOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=1.000000
I20260812 06:17:50.977453 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: MajorDeltaCompactionOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.126s	user 0.105s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":454,"lbm_read_time_us":8554,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26543,"lbm_writes_lt_1ms":443,"mutex_wait_us":78,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:50.978191 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=10.126437
I20260812 06:17:51.025282 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.047s	user 0.031s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16583,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:51.026077 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=2.188937
I20260812 06:17:51.042465 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.016s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5993,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:51.043013 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling MajorDeltaCompactionOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=1.000000
I20260812 06:17:51.169191 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: MajorDeltaCompactionOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.126s	user 0.101s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2116,"lbm_read_time_us":8693,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25057,"lbm_writes_lt_1ms":443,"mutex_wait_us":821,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16000,"update_count":2000}
I20260812 06:17:51.170123 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=10.126437
I20260812 06:17:51.219868 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.050s	user 0.033s	sys 0.004s Metrics: {"bytes_written":12307504,"delete_count":0,"lbm_write_time_us":17273,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:51.220439 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=2.188937
I20260812 06:17:51.233932 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.013s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4959,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:51.234500 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling MajorDeltaCompactionOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=1.000000
I20260812 06:17:51.366956 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: MajorDeltaCompactionOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.132s	user 0.108s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672291,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":949,"lbm_read_time_us":10441,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25621,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:17:51.367815 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=11.118625
I20260812 06:17:51.419589 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.051s	user 0.026s	sys 0.023s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":21492,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:51.420220 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=2.188937
I20260812 06:17:51.434134 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.014s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3919,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:51.434657 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling MajorDeltaCompactionOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=1.000000
I20260812 06:17:51.585656 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: MajorDeltaCompactionOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.151s	user 0.089s	sys 0.056s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":229,"lbm_read_time_us":8933,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23755,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2000}
I20260812 06:17:51.586247 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=14.095187
I20260812 06:17:51.649295 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.063s	user 0.030s	sys 0.028s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":27729,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:51.649964 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=2.188937
I20260812 06:17:51.661339 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3929,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:51.661966 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushMRSOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=1.000000
I20260812 06:17:51.697894 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushMRSOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.036s	user 0.029s	sys 0.004s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":295,"dirs.run_wall_time_us":1722,"drs_written":1,"lbm_read_time_us":127,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2322,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:51.699129 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=2.188937
I20260812 06:17:51.711159 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4455,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:51.711694 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling LogGCOp(22f3168aa0a7423bab9e15fa2b36cc79): free 128867446 bytes of WAL
I20260812 06:17:51.711939 32502 log_reader.cc:385] T 22f3168aa0a7423bab9e15fa2b36cc79: removed 13 log segments from log reader
I20260812 06:17:51.711998 32502 log.cc:1079] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/22f3168aa0a7423bab9e15fa2b36cc79/wal-000000014 (ops 66-70)
I20260812 06:17:51.712131 32502 log.cc:1079] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/22f3168aa0a7423bab9e15fa2b36cc79/wal-000000015 (ops 71-75)
I20260812 06:17:51.712220 32502 log.cc:1079] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/22f3168aa0a7423bab9e15fa2b36cc79/wal-000000016 (ops 76-80)
I20260812 06:17:51.712276 32502 log.cc:1079] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/22f3168aa0a7423bab9e15fa2b36cc79/wal-000000017 (ops 81-84)
I20260812 06:17:51.712333 32502 log.cc:1079] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/22f3168aa0a7423bab9e15fa2b36cc79/wal-000000018 (ops 85-89)
I20260812 06:17:51.712384 32502 log.cc:1079] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/22f3168aa0a7423bab9e15fa2b36cc79/wal-000000019 (ops 90-94)
I20260812 06:17:51.712443 32502 log.cc:1079] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/22f3168aa0a7423bab9e15fa2b36cc79/wal-000000020 (ops 95-99)
I20260812 06:17:51.712502 32502 log.cc:1079] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/22f3168aa0a7423bab9e15fa2b36cc79/wal-000000021 (ops 100-104)
I20260812 06:17:51.712559 32502 log.cc:1079] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/22f3168aa0a7423bab9e15fa2b36cc79/wal-000000022 (ops 105-108)
I20260812 06:17:51.712620 32502 log.cc:1079] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/22f3168aa0a7423bab9e15fa2b36cc79/wal-000000023 (ops 109-113)
I20260812 06:17:51.712677 32502 log.cc:1079] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/22f3168aa0a7423bab9e15fa2b36cc79/wal-000000024 (ops 114-118)
I20260812 06:17:51.712736 32502 log.cc:1079] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/22f3168aa0a7423bab9e15fa2b36cc79/wal-000000025 (ops 119-122)
I20260812 06:17:51.712795 32502 log.cc:1079] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/22f3168aa0a7423bab9e15fa2b36cc79/wal-000000026 (ops 123-127)
I20260812 06:17:51.745103 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: LogGCOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.033s	user 0.003s	sys 0.027s Metrics: {}
I20260812 06:17:51.745889 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling UndoDeltaBlockGCOp(22f3168aa0a7423bab9e15fa2b36cc79): 483 bytes on disk
I20260812 06:17:51.746394 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: UndoDeltaBlockGCOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4}
I20260812 06:17:51.747090 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=1.000000
I20260812 06:17:51.754145 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.007s	user 0.002s	sys 0.004s Metrics: {"bytes_written":1969356,"delete_count":0,"lbm_write_time_us":2117,"lbm_writes_lt_1ms":51,"reinsert_count":0,"update_count":240}
I20260812 06:17:51.754652 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=1.000000
I20260812 06:17:51.761317 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.006s	user 0.001s	sys 0.004s Metrics: {"bytes_written":2133453,"delete_count":0,"lbm_write_time_us":2198,"lbm_writes_lt_1ms":55,"reinsert_count":0,"update_count":260}
I20260812 06:17:51.761847 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling MajorDeltaCompactionOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=1.000000
I20260812 06:17:52.000295 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: MajorDeltaCompactionOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.238s	user 0.148s	sys 0.086s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979776,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":2646,"lbm_read_time_us":15596,"lbm_reads_lt_1ms":775,"lbm_write_time_us":37605,"lbm_writes_lt_1ms":743,"mutex_wait_us":23,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2816,"thread_start_us":101,"threads_started":1,"update_count":3500}
I20260812 06:17:52.001083 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=18.063937
I20260812 06:17:52.071210 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.070s	user 0.029s	sys 0.027s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":26191,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:52.071732 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=2.188937
I20260812 06:17:52.082855 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4146,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:52.083686 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling MajorDeltaCompactionOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=1.000000
I20260812 06:17:52.303859 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: MajorDeltaCompactionOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.220s	user 0.170s	sys 0.048s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":901,"lbm_read_time_us":13097,"lbm_reads_lt_1ms":672,"lbm_write_time_us":37209,"lbm_writes_lt_1ms":643,"mutex_wait_us":591,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":15744,"update_count":3000}
I20260812 06:17:52.304955 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=14.095187
I20260812 06:17:52.344657 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.039s	user 0.030s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17365,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:52.345628 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=2.188937
I20260812 06:17:52.365846 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.020s	user 0.003s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6044,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:52.366442 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling MajorDeltaCompactionOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=1.000000
I20260812 06:17:52.577389 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: MajorDeltaCompactionOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.211s	user 0.139s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":451,"lbm_read_time_us":12240,"lbm_reads_lt_1ms":564,"lbm_write_time_us":33124,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:52.578265 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=18.063937
I20260812 06:17:52.649955 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.071s	user 0.053s	sys 0.008s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":27180,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:52.650549 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=2.188937
I20260812 06:17:52.661515 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.011s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4106,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:52.662447 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling MajorDeltaCompactionOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=1.000000
I20260812 06:17:52.870811 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: MajorDeltaCompactionOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.208s	user 0.138s	sys 0.069s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877105,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":273,"lbm_read_time_us":15927,"lbm_reads_lt_1ms":672,"lbm_write_time_us":32314,"lbm_writes_lt_1ms":643,"mutex_wait_us":43,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":3000}
I20260812 06:17:52.871570 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=14.095187
I20260812 06:17:52.922936 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.051s	user 0.034s	sys 0.015s Metrics: {"bytes_written":16409950,"delete_count":0,"lbm_write_time_us":21336,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:52.923610 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=2.188937
I20260812 06:17:52.935040 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4399,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:52.935597 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling MajorDeltaCompactionOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=1.000000
I20260812 06:17:53.119787 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: MajorDeltaCompactionOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.184s	user 0.146s	sys 0.031s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774737,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":204,"lbm_read_time_us":13208,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29068,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19712,"update_count":2500}
I20260812 06:17:53.120628 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=14.095187
I20260812 06:17:53.188040 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.067s	user 0.026s	sys 0.039s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":27858,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:53.188787 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=2.188937
I20260812 06:17:53.199519 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4098,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:53.200032 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushMRSOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=1.000000
I20260812 06:17:53.238916 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushMRSOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.039s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":204,"dirs.run_wall_time_us":1398,"drs_written":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2061,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:53.239672 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling LogGCOp(22f3168aa0a7423bab9e15fa2b36cc79): free 120553692 bytes of WAL
I20260812 06:17:53.239954 32502 log_reader.cc:385] T 22f3168aa0a7423bab9e15fa2b36cc79: removed 12 log segments from log reader
I20260812 06:17:53.240003 32502 log.cc:1079] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/22f3168aa0a7423bab9e15fa2b36cc79/wal-000000027 (ops 128-132)
I20260812 06:17:53.240033 32502 log.cc:1079] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/22f3168aa0a7423bab9e15fa2b36cc79/wal-000000028 (ops 133-136)
I20260812 06:17:53.240093 32502 log.cc:1079] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/22f3168aa0a7423bab9e15fa2b36cc79/wal-000000029 (ops 137-141)
I20260812 06:17:53.240147 32502 log.cc:1079] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/22f3168aa0a7423bab9e15fa2b36cc79/wal-000000030 (ops 142-146)
I20260812 06:17:53.240214 32502 log.cc:1079] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/22f3168aa0a7423bab9e15fa2b36cc79/wal-000000031 (ops 147-151)
I20260812 06:17:53.240252 32502 log.cc:1079] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/22f3168aa0a7423bab9e15fa2b36cc79/wal-000000032 (ops 152-156)
I20260812 06:17:53.240298 32502 log.cc:1079] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/22f3168aa0a7423bab9e15fa2b36cc79/wal-000000033 (ops 157-161)
I20260812 06:17:53.240338 32502 log.cc:1079] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/22f3168aa0a7423bab9e15fa2b36cc79/wal-000000034 (ops 162-166)
I20260812 06:17:53.240377 32502 log.cc:1079] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/22f3168aa0a7423bab9e15fa2b36cc79/wal-000000035 (ops 167-170)
I20260812 06:17:53.240417 32502 log.cc:1079] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/22f3168aa0a7423bab9e15fa2b36cc79/wal-000000036 (ops 171-175)
I20260812 06:17:53.240456 32502 log.cc:1079] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/22f3168aa0a7423bab9e15fa2b36cc79/wal-000000037 (ops 176-180)
I20260812 06:17:53.240495 32502 log.cc:1079] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: Deleting log segment in path: /tmp/dist-test-taskUH8VTZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515462558156-32175-0/minicluster-data/ts-0-root/wals/22f3168aa0a7423bab9e15fa2b36cc79/wal-000000038 (ops 181-185)
I20260812 06:17:53.267570 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: LogGCOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:53.268015 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling UndoDeltaBlockGCOp(22f3168aa0a7423bab9e15fa2b36cc79): 462 bytes on disk
I20260812 06:17:53.268603 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: UndoDeltaBlockGCOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:17:53.269244 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=2.188937
I20260812 06:17:53.291054 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.022s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6269,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:53.291613 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=2.188937
I20260812 06:17:53.302574 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4208,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:53.303093 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling MajorDeltaCompactionOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=1.000000
I20260812 06:17:53.556154 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: MajorDeltaCompactionOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.253s	user 0.161s	sys 0.080s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979749,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":595,"lbm_read_time_us":16568,"lbm_reads_lt_1ms":774,"lbm_write_time_us":42698,"lbm_writes_lt_1ms":743,"mutex_wait_us":569,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":14208,"thread_start_us":83,"threads_started":1,"update_count":3500}
I20260812 06:17:53.557050 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=18.063937
I20260812 06:17:53.618510 32175 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.087s	user 1.858s	sys 0.165s
I20260812 06:17:53.622758 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.065s	user 0.047s	sys 0.014s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":27964,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:53.623325 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=2.188937
I20260812 06:17:53.636495 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: FlushDeltaMemStoresOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.013s	user 0.000s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5614,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":500}
I20260812 06:17:53.637048 32571 maintenance_manager.cc:419] P b50740b6d34943d69077d44584907107: Scheduling MajorDeltaCompactionOp(22f3168aa0a7423bab9e15fa2b36cc79): perf score=1.000000
I20260812 06:17:53.674154 32175 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.055s	user 0.003s	sys 0.000s
I20260812 06:17:53.674700 32175 tablet_server.cc:179] TabletServer@127.31.107.193:0 shutting down...
I20260812 06:17:53.776678 32502 maintenance_manager.cc:643] P b50740b6d34943d69077d44584907107: MajorDeltaCompactionOp(22f3168aa0a7423bab9e15fa2b36cc79) complete. Timing: real 0.139s	user 0.103s	sys 0.036s Metrics: {"cfile_cache_hit":391,"cfile_cache_hit_bytes":16000972,"cfile_cache_miss":241,"cfile_cache_miss_bytes":12876131,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1051,"lbm_read_time_us":5232,"lbm_reads_lt_1ms":273,"lbm_write_time_us":29996,"lbm_writes_lt_1ms":643,"mutex_wait_us":85,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":49536,"update_count":3000}
I20260812 06:17:53.777520 32175 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:53.777817 32175 tablet_replica.cc:333] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107: stopping tablet replica
I20260812 06:17:53.777976 32175 raft_consensus.cc:2243] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:53.778192 32175 raft_consensus.cc:2272] T 22f3168aa0a7423bab9e15fa2b36cc79 P b50740b6d34943d69077d44584907107 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:53.783356 32175 tablet_server.cc:196] TabletServer@127.31.107.193:0 shutdown complete.
I20260812 06:17:53.830436 32175 master.cc:562] Master@127.31.107.254:44881 shutting down...
I20260812 06:17:53.834561 32175 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 0fd37d6be3124236b667eb960217f9d1 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:53.834765 32175 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 0fd37d6be3124236b667eb960217f9d1 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:53.834818 32175 tablet_replica.cc:333] T 00000000000000000000000000000000 P 0fd37d6be3124236b667eb960217f9d1: stopping tablet replica
I20260812 06:17:53.847433 32175 master.cc:584] Master@127.31.107.254:44881 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5643 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11382 ms total)

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