[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:19:13.437561 14519 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.14.45.254:41351
I20260812 06:19:13.438567 14519 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:19:13.439181 14519 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:19:13.445478 14519 server_base.cc:1061] running on GCE node
W20260812 06:19:13.445600 14527 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:13.445803 14529 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:13.445883 14526 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:13.446365 14519 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:13.446468 14519 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:13.446511 14519 hybrid_clock.cc:648] HybridClock initialized: now 1786515553446507 us; error 0 us; skew 500 ppm
I20260812 06:19:13.448137 14519 webserver.cc:533] Webserver started at http://127.14.45.254:32853/ using document root <none> and password file <none>
I20260812 06:19:13.448679 14519 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:13.448734 14519 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:13.448963 14519 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:13.450639 14519 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/master-0-root/instance:
uuid: "4ba0629ce63d4c76a764cb2d3d865f02"
format_stamp: "Formatted at 2026-08-12 06:19:13 on dist-test-slave-vq2q"
I20260812 06:19:13.453977 14519 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.001s	sys 0.003s
I20260812 06:19:13.455997 14535 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:13.456954 14519 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.001s
I20260812 06:19:13.457062 14519 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/master-0-root
uuid: "4ba0629ce63d4c76a764cb2d3d865f02"
format_stamp: "Formatted at 2026-08-12 06:19:13 on dist-test-slave-vq2q"
I20260812 06:19:13.457147 14519 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:13.472424 14519 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:13.473037 14519 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:19:13.473218 14519 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:13.480484 14595 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.14.45.254:41351 every 8 connection(s)
I20260812 06:19:13.480490 14519 rpc_server.cc:307] RPC server started. Bound to: 127.14.45.254:41351
I20260812 06:19:13.482857 14596 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:13.488420 14596 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4ba0629ce63d4c76a764cb2d3d865f02: Bootstrap starting.
I20260812 06:19:13.490875 14596 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 4ba0629ce63d4c76a764cb2d3d865f02: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:13.491750 14596 log.cc:826] T 00000000000000000000000000000000 P 4ba0629ce63d4c76a764cb2d3d865f02: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:13.493521 14596 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4ba0629ce63d4c76a764cb2d3d865f02: No bootstrap required, opened a new log
I20260812 06:19:13.496281 14596 raft_consensus.cc:359] T 00000000000000000000000000000000 P 4ba0629ce63d4c76a764cb2d3d865f02 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4ba0629ce63d4c76a764cb2d3d865f02" member_type: VOTER }
I20260812 06:19:13.496457 14596 raft_consensus.cc:385] T 00000000000000000000000000000000 P 4ba0629ce63d4c76a764cb2d3d865f02 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:13.496518 14596 raft_consensus.cc:740] T 00000000000000000000000000000000 P 4ba0629ce63d4c76a764cb2d3d865f02 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4ba0629ce63d4c76a764cb2d3d865f02, State: Initialized, Role: FOLLOWER
I20260812 06:19:13.497061 14596 consensus_queue.cc:260] T 00000000000000000000000000000000 P 4ba0629ce63d4c76a764cb2d3d865f02 [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: "4ba0629ce63d4c76a764cb2d3d865f02" member_type: VOTER }
I20260812 06:19:13.497221 14596 raft_consensus.cc:399] T 00000000000000000000000000000000 P 4ba0629ce63d4c76a764cb2d3d865f02 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:13.497282 14596 raft_consensus.cc:493] T 00000000000000000000000000000000 P 4ba0629ce63d4c76a764cb2d3d865f02 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:13.497377 14596 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 4ba0629ce63d4c76a764cb2d3d865f02 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:13.498095 14596 raft_consensus.cc:515] T 00000000000000000000000000000000 P 4ba0629ce63d4c76a764cb2d3d865f02 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4ba0629ce63d4c76a764cb2d3d865f02" member_type: VOTER }
I20260812 06:19:13.498493 14596 leader_election.cc:304] T 00000000000000000000000000000000 P 4ba0629ce63d4c76a764cb2d3d865f02 [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: 4ba0629ce63d4c76a764cb2d3d865f02; no voters: 
I20260812 06:19:13.498754 14596 leader_election.cc:290] T 00000000000000000000000000000000 P 4ba0629ce63d4c76a764cb2d3d865f02 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:13.498878 14599 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 4ba0629ce63d4c76a764cb2d3d865f02 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:13.499086 14599 raft_consensus.cc:697] T 00000000000000000000000000000000 P 4ba0629ce63d4c76a764cb2d3d865f02 [term 1 LEADER]: Becoming Leader. State: Replica: 4ba0629ce63d4c76a764cb2d3d865f02, State: Running, Role: LEADER
I20260812 06:19:13.499507 14599 consensus_queue.cc:237] T 00000000000000000000000000000000 P 4ba0629ce63d4c76a764cb2d3d865f02 [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: "4ba0629ce63d4c76a764cb2d3d865f02" member_type: VOTER }
I20260812 06:19:13.499724 14596 sys_catalog.cc:565] T 00000000000000000000000000000000 P 4ba0629ce63d4c76a764cb2d3d865f02 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:13.501420 14601 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4ba0629ce63d4c76a764cb2d3d865f02 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 4ba0629ce63d4c76a764cb2d3d865f02. Latest consensus state: current_term: 1 leader_uuid: "4ba0629ce63d4c76a764cb2d3d865f02" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4ba0629ce63d4c76a764cb2d3d865f02" member_type: VOTER } }
I20260812 06:19:13.501451 14600 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4ba0629ce63d4c76a764cb2d3d865f02 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "4ba0629ce63d4c76a764cb2d3d865f02" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4ba0629ce63d4c76a764cb2d3d865f02" member_type: VOTER } }
I20260812 06:19:13.501571 14601 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4ba0629ce63d4c76a764cb2d3d865f02 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:13.501572 14600 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4ba0629ce63d4c76a764cb2d3d865f02 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:13.501967 14519 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:13.501997 14616 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:13.504185 14616 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:13.509231 14616 catalog_manager.cc:1383] Generated new cluster ID: 69ee3af19ea545a1b505ded207bbd578
I20260812 06:19:13.509310 14616 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:13.521109 14616 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:13.522303 14616 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:13.533457 14616 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 4ba0629ce63d4c76a764cb2d3d865f02: Generated new TSK 0
I20260812 06:19:13.534323 14616 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:13.566792 14519 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:13.569561 14624 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:13.569615 14621 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:13.569577 14622 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:13.569959 14519 server_base.cc:1061] running on GCE node
I20260812 06:19:13.570125 14519 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:13.570166 14519 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:13.570188 14519 hybrid_clock.cc:648] HybridClock initialized: now 1786515553570188 us; error 0 us; skew 500 ppm
I20260812 06:19:13.571095 14519 webserver.cc:533] Webserver started at http://127.14.45.193:32979/ using document root <none> and password file <none>
I20260812 06:19:13.571275 14519 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:13.571332 14519 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:13.571409 14519 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:13.571851 14519 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/instance:
uuid: "45c4d23907da449cbe2d8ed56dd534d4"
format_stamp: "Formatted at 2026-08-12 06:19:13 on dist-test-slave-vq2q"
I20260812 06:19:13.574049 14519 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:13.575165 14631 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:13.575456 14519 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:13.575531 14519 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root
uuid: "45c4d23907da449cbe2d8ed56dd534d4"
format_stamp: "Formatted at 2026-08-12 06:19:13 on dist-test-slave-vq2q"
I20260812 06:19:13.575606 14519 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:13.604305 14519 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:13.604748 14519 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:13.605274 14519 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:13.606165 14519 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:13.606220 14519 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:13.606281 14519 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:13.606308 14519 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:13.612385 14519 rpc_server.cc:307] RPC server started. Bound to: 127.14.45.193:37463
I20260812 06:19:13.612437 14712 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.14.45.193:37463 every 8 connection(s)
I20260812 06:19:13.624995 14713 heartbeater.cc:344] Connected to a master server at 127.14.45.254:41351
I20260812 06:19:13.625314 14713 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:13.625895 14713 heartbeater.cc:507] Master 127.14.45.254:41351 requested a full tablet report, sending...
I20260812 06:19:13.627476 14556 ts_manager.cc:194] Registered new tserver with Master: 45c4d23907da449cbe2d8ed56dd534d4 (127.14.45.193:37463)
I20260812 06:19:13.627578 14519 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01458779s
I20260812 06:19:13.628752 14556 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:44110
I20260812 06:19:13.638195 14556 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:44116:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:13.651731 14671 tablet_service.cc:1511] Processing CreateTablet for tablet 14bd1f57cdc942ceb6d4b1e4ce4b2094 (DEFAULT_TABLE table=heavy-update-compaction-test [id=7c70d81c9c254e98959044bc76a28fcb]), partition=
I20260812 06:19:13.652257 14671 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 14bd1f57cdc942ceb6d4b1e4ce4b2094. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:13.654544 14727 tablet_bootstrap.cc:492] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Bootstrap starting.
I20260812 06:19:13.655828 14727 tablet_bootstrap.cc:654] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:13.656940 14727 tablet_bootstrap.cc:492] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: No bootstrap required, opened a new log
I20260812 06:19:13.657030 14727 ts_tablet_manager.cc:1403] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:13.657543 14727 raft_consensus.cc:359] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "45c4d23907da449cbe2d8ed56dd534d4" member_type: VOTER last_known_addr { host: "127.14.45.193" port: 37463 } }
I20260812 06:19:13.657644 14727 raft_consensus.cc:385] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:13.657667 14727 raft_consensus.cc:740] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 45c4d23907da449cbe2d8ed56dd534d4, State: Initialized, Role: FOLLOWER
I20260812 06:19:13.657797 14727 consensus_queue.cc:260] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4 [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: "45c4d23907da449cbe2d8ed56dd534d4" member_type: VOTER last_known_addr { host: "127.14.45.193" port: 37463 } }
I20260812 06:19:13.657869 14727 raft_consensus.cc:399] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:13.657897 14727 raft_consensus.cc:493] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:13.657943 14727 raft_consensus.cc:3060] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:13.658638 14727 raft_consensus.cc:515] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "45c4d23907da449cbe2d8ed56dd534d4" member_type: VOTER last_known_addr { host: "127.14.45.193" port: 37463 } }
I20260812 06:19:13.658782 14727 leader_election.cc:304] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4 [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: 45c4d23907da449cbe2d8ed56dd534d4; no voters: 
I20260812 06:19:13.658979 14727 leader_election.cc:290] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:13.659081 14729 raft_consensus.cc:2804] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:13.659396 14727 ts_tablet_manager.cc:1434] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:13.659530 14729 raft_consensus.cc:697] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4 [term 1 LEADER]: Becoming Leader. State: Replica: 45c4d23907da449cbe2d8ed56dd534d4, State: Running, Role: LEADER
I20260812 06:19:13.659578 14713 heartbeater.cc:499] Master 127.14.45.254:41351 was elected leader, sending a full tablet report...
I20260812 06:19:13.659819 14729 consensus_queue.cc:237] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4 [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: "45c4d23907da449cbe2d8ed56dd534d4" member_type: VOTER last_known_addr { host: "127.14.45.193" port: 37463 } }
I20260812 06:19:13.662575 14556 catalog_manager.cc:5719] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4 reported cstate change: term changed from 0 to 1, leader changed from <none> to 45c4d23907da449cbe2d8ed56dd534d4 (127.14.45.193). New cstate: current_term: 1 leader_uuid: "45c4d23907da449cbe2d8ed56dd534d4" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "45c4d23907da449cbe2d8ed56dd534d4" member_type: VOTER last_known_addr { host: "127.14.45.193" port: 37463 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:13.723806 14519 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.052s	user 0.018s	sys 0.007s
I20260812 06:19:13.863494 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushMRSOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=19.054940
I20260812 06:19:14.044454 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushMRSOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.181s	user 0.139s	sys 0.036s Metrics: {"bytes_written":12840807,"cfile_init":1,"compiler_manager_pool.queue_time_us":209,"delete_count":0,"dirs.queue_time_us":40,"dirs.run_cpu_time_us":240,"dirs.run_wall_time_us":928,"drs_written":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42370,"lbm_writes_lt_1ms":770,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":288128,"thread_start_us":116,"threads_started":1,"update_count":1565}
I20260812 06:19:14.045715 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling LogGCOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): free 20743880 bytes of WAL
I20260812 06:19:14.046068 14637 log_reader.cc:385] T 14bd1f57cdc942ceb6d4b1e4ce4b2094: removed 2 log segments from log reader
I20260812 06:19:14.046149 14637 log.cc:1079] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/14bd1f57cdc942ceb6d4b1e4ce4b2094/wal-000000001 (ops 1-6)
I20260812 06:19:14.046276 14637 log.cc:1079] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/14bd1f57cdc942ceb6d4b1e4ce4b2094/wal-000000002 (ops 7-11)
I20260812 06:19:14.051307 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: LogGCOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:19:14.051791 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling UndoDeltaBlockGCOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): 16411392 bytes on disk
I20260812 06:19:14.052567 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: UndoDeltaBlockGCOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":88,"lbm_reads_lt_1ms":4}
I20260812 06:19:14.053047 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=4.173312
I20260812 06:19:14.079489 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.026s	user 0.013s	sys 0.011s Metrics: {"bytes_written":5989774,"delete_count":0,"lbm_write_time_us":8314,"lbm_writes_lt_1ms":149,"reinsert_count":0,"update_count":730}
I20260812 06:19:14.080082 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=1.000000
I20260812 06:19:14.090471 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.010s	user 0.003s	sys 0.003s Metrics: {"bytes_written":1682177,"delete_count":0,"lbm_write_time_us":2136,"lbm_writes_lt_1ms":44,"reinsert_count":0,"update_count":205}
I20260812 06:19:14.090951 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling MajorDeltaCompactionOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=1.000000
I20260812 06:19:14.250836 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: MajorDeltaCompactionOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.160s	user 0.120s	sys 0.040s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774753,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1210,"lbm_read_time_us":10511,"lbm_reads_lt_1ms":565,"lbm_write_time_us":26681,"lbm_writes_lt_1ms":543,"mutex_wait_us":280,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":330,"threads_started":5,"update_count":2500}
I20260812 06:19:14.251483 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=10.126437
I20260812 06:19:14.293656 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.042s	user 0.020s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15794,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:14.294217 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=2.188937
I20260812 06:19:14.321724 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.027s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5485,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:14.322291 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=2.188937
I20260812 06:19:14.334849 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4139,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:14.335664 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling MajorDeltaCompactionOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=1.000000
I20260812 06:19:14.499100 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: MajorDeltaCompactionOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.163s	user 0.107s	sys 0.051s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774808,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":207,"lbm_read_time_us":9527,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27156,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:19:14.499770 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=10.126437
I20260812 06:19:14.540761 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.041s	user 0.031s	sys 0.004s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":16091,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:14.541427 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=2.188937
I20260812 06:19:14.556797 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5725,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:14.557315 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling MajorDeltaCompactionOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=1.000000
I20260812 06:19:14.684149 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: MajorDeltaCompactionOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.127s	user 0.094s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672280,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":128,"lbm_read_time_us":9223,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23460,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":46336,"update_count":2000}
I20260812 06:19:14.684787 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=10.126437
I20260812 06:19:14.724373 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.039s	user 0.024s	sys 0.012s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":16110,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:14.724876 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=2.188937
I20260812 06:19:14.735257 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3729,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:14.735718 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling MajorDeltaCompactionOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=1.000000
I20260812 06:19:14.850078 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: MajorDeltaCompactionOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.114s	user 0.098s	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":923,"lbm_read_time_us":8052,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20333,"lbm_writes_lt_1ms":443,"mutex_wait_us":252,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":2000}
I20260812 06:19:14.850657 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=10.126437
I20260812 06:19:14.897838 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.047s	user 0.016s	sys 0.023s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14727,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:14.898522 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=2.188937
I20260812 06:19:14.914183 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5889,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:14.914719 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling MajorDeltaCompactionOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=1.000000
I20260812 06:19:15.055706 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: MajorDeltaCompactionOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.141s	user 0.097s	sys 0.044s 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":956,"lbm_read_time_us":10403,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22343,"lbm_writes_lt_1ms":443,"mutex_wait_us":251,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:19:15.056228 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=10.126437
I20260812 06:19:15.100576 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.044s	user 0.012s	sys 0.028s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15190,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:15.101080 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=2.188937
I20260812 06:19:15.111198 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3579,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:15.112087 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling MajorDeltaCompactionOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=1.000000
I20260812 06:19:15.234797 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: MajorDeltaCompactionOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.123s	user 0.098s	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":184,"lbm_read_time_us":8436,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20499,"lbm_writes_lt_1ms":443,"mutex_wait_us":19,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2000}
I20260812 06:19:15.235280 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=10.126437
I20260812 06:19:15.275617 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.040s	user 0.013s	sys 0.019s Metrics: {"bytes_written":12307495,"delete_count":0,"lbm_write_time_us":15813,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:15.276253 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=2.188937
I20260812 06:19:15.286190 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3695,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:15.286684 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushMRSOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=1.000000
I20260812 06:19:15.313704 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushMRSOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.027s	user 0.024s	sys 0.002s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":79,"dirs.run_cpu_time_us":268,"dirs.run_wall_time_us":1401,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1364,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:15.314533 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling LogGCOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): free 120553389 bytes of WAL
I20260812 06:19:15.314764 14637 log_reader.cc:385] T 14bd1f57cdc942ceb6d4b1e4ce4b2094: removed 12 log segments from log reader
I20260812 06:19:15.314824 14637 log.cc:1079] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/14bd1f57cdc942ceb6d4b1e4ce4b2094/wal-000000003 (ops 12-16)
I20260812 06:19:15.314870 14637 log.cc:1079] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/14bd1f57cdc942ceb6d4b1e4ce4b2094/wal-000000004 (ops 17-21)
I20260812 06:19:15.314905 14637 log.cc:1079] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/14bd1f57cdc942ceb6d4b1e4ce4b2094/wal-000000005 (ops 22-26)
I20260812 06:19:15.314935 14637 log.cc:1079] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/14bd1f57cdc942ceb6d4b1e4ce4b2094/wal-000000006 (ops 27-30)
I20260812 06:19:15.314963 14637 log.cc:1079] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/14bd1f57cdc942ceb6d4b1e4ce4b2094/wal-000000007 (ops 31-35)
I20260812 06:19:15.314990 14637 log.cc:1079] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/14bd1f57cdc942ceb6d4b1e4ce4b2094/wal-000000008 (ops 36-40)
I20260812 06:19:15.315021 14637 log.cc:1079] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/14bd1f57cdc942ceb6d4b1e4ce4b2094/wal-000000009 (ops 41-45)
I20260812 06:19:15.315052 14637 log.cc:1079] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/14bd1f57cdc942ceb6d4b1e4ce4b2094/wal-000000010 (ops 46-50)
I20260812 06:19:15.315079 14637 log.cc:1079] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/14bd1f57cdc942ceb6d4b1e4ce4b2094/wal-000000011 (ops 51-55)
I20260812 06:19:15.315106 14637 log.cc:1079] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/14bd1f57cdc942ceb6d4b1e4ce4b2094/wal-000000012 (ops 56-60)
I20260812 06:19:15.315135 14637 log.cc:1079] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/14bd1f57cdc942ceb6d4b1e4ce4b2094/wal-000000013 (ops 61-64)
I20260812 06:19:15.315163 14637 log.cc:1079] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/14bd1f57cdc942ceb6d4b1e4ce4b2094/wal-000000014 (ops 65-69)
I20260812 06:19:15.339691 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: LogGCOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.025s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:19:15.340094 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=3.181125
I20260812 06:19:15.354219 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.014s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":3876,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:15.354643 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling UndoDeltaBlockGCOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): 472 bytes on disk
I20260812 06:19:15.355051 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: UndoDeltaBlockGCOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:19:15.355496 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=2.188937
I20260812 06:19:15.364696 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3310,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:15.365082 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling MajorDeltaCompactionOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=1.000000
I20260812 06:19:15.540879 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: MajorDeltaCompactionOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.176s	user 0.120s	sys 0.045s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877331,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":4081,"lbm_read_time_us":10020,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33494,"lbm_writes_lt_1ms":643,"mutex_wait_us":51,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":112,"threads_started":1,"update_count":3000}
I20260812 06:19:15.541508 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=14.095187
I20260812 06:19:15.582271 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.041s	user 0.032s	sys 0.004s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":15992,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:19:15.582894 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=2.188937
I20260812 06:19:15.594705 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3701,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:15.595239 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling MajorDeltaCompactionOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=1.000000
I20260812 06:19:15.741070 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: MajorDeltaCompactionOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.146s	user 0.117s	sys 0.024s 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":938,"lbm_read_time_us":10822,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27299,"lbm_writes_lt_1ms":543,"mutex_wait_us":266,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2500}
I20260812 06:19:15.741676 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=11.118625
I20260812 06:19:15.770712 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.029s	user 0.012s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12631,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:15.771214 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=2.188937
I20260812 06:19:15.784296 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.013s	user 0.007s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4812,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:15.784780 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling MajorDeltaCompactionOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=1.000000
I20260812 06:19:15.915045 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: MajorDeltaCompactionOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.130s	user 0.083s	sys 0.045s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":108,"lbm_read_time_us":8799,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21914,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:19:15.915792 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=10.126437
I20260812 06:19:15.954911 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.039s	user 0.024s	sys 0.013s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13704,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:15.955516 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=2.188937
I20260812 06:19:15.969172 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4849,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:15.969653 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling MajorDeltaCompactionOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=1.000000
I20260812 06:19:16.103252 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: MajorDeltaCompactionOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.133s	user 0.093s	sys 0.038s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":324,"lbm_read_time_us":9910,"lbm_reads_lt_1ms":468,"lbm_write_time_us":20572,"lbm_writes_lt_1ms":443,"mutex_wait_us":58,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:19:16.103879 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=10.126437
I20260812 06:19:16.143498 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.039s	user 0.027s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16138,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:16.144037 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=2.188937
I20260812 06:19:16.159327 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5799,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:16.159936 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling MajorDeltaCompactionOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=1.000000
I20260812 06:19:16.276752 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: MajorDeltaCompactionOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.117s	user 0.090s	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":1031,"lbm_read_time_us":7684,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20715,"lbm_writes_lt_1ms":443,"mutex_wait_us":264,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15104,"update_count":2000}
I20260812 06:19:16.277505 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=10.126437
I20260812 06:19:16.308709 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.031s	user 0.014s	sys 0.014s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12965,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:16.309238 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=2.188937
I20260812 06:19:16.324344 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5466,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:16.324893 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling MajorDeltaCompactionOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=1.000000
I20260812 06:19:16.441335 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: MajorDeltaCompactionOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.116s	user 0.096s	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":309,"lbm_read_time_us":8253,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22763,"lbm_writes_lt_1ms":443,"mutex_wait_us":62,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":47232,"update_count":2000}
I20260812 06:19:16.441843 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=10.126437
I20260812 06:19:16.494669 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.053s	user 0.012s	sys 0.030s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15238,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:16.495236 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=2.188937
I20260812 06:19:16.510262 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.015s	user 0.012s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5759,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:16.510787 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling MajorDeltaCompactionOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=1.000000
I20260812 06:19:16.647792 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: MajorDeltaCompactionOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.137s	user 0.090s	sys 0.045s 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":647,"lbm_read_time_us":9646,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21308,"lbm_writes_lt_1ms":443,"mutex_wait_us":69,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:16.648294 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=10.126437
I20260812 06:19:16.690549 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.042s	user 0.022s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13246,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:16.691082 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=2.188937
I20260812 06:19:16.701292 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.010s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3858,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:16.701946 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushMRSOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=1.000000
I20260812 06:19:16.731601 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushMRSOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.029s	user 0.024s	sys 0.003s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":52,"dirs.run_cpu_time_us":220,"dirs.run_wall_time_us":1165,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1936,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:16.732375 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling LogGCOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): free 132571330 bytes of WAL
I20260812 06:19:16.732640 14637 log_reader.cc:385] T 14bd1f57cdc942ceb6d4b1e4ce4b2094: removed 13 log segments from log reader
I20260812 06:19:16.732684 14637 log.cc:1079] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/14bd1f57cdc942ceb6d4b1e4ce4b2094/wal-000000015 (ops 70-74)
I20260812 06:19:16.732725 14637 log.cc:1079] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/14bd1f57cdc942ceb6d4b1e4ce4b2094/wal-000000016 (ops 75-78)
I20260812 06:19:16.732765 14637 log.cc:1079] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/14bd1f57cdc942ceb6d4b1e4ce4b2094/wal-000000017 (ops 79-83)
I20260812 06:19:16.732798 14637 log.cc:1079] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/14bd1f57cdc942ceb6d4b1e4ce4b2094/wal-000000018 (ops 84-88)
I20260812 06:19:16.732831 14637 log.cc:1079] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/14bd1f57cdc942ceb6d4b1e4ce4b2094/wal-000000019 (ops 89-93)
I20260812 06:19:16.732860 14637 log.cc:1079] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/14bd1f57cdc942ceb6d4b1e4ce4b2094/wal-000000020 (ops 94-98)
I20260812 06:19:16.732892 14637 log.cc:1079] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/14bd1f57cdc942ceb6d4b1e4ce4b2094/wal-000000021 (ops 99-103)
I20260812 06:19:16.732923 14637 log.cc:1079] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/14bd1f57cdc942ceb6d4b1e4ce4b2094/wal-000000022 (ops 104-108)
I20260812 06:19:16.732954 14637 log.cc:1079] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/14bd1f57cdc942ceb6d4b1e4ce4b2094/wal-000000023 (ops 109-113)
I20260812 06:19:16.732985 14637 log.cc:1079] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/14bd1f57cdc942ceb6d4b1e4ce4b2094/wal-000000024 (ops 114-118)
I20260812 06:19:16.733014 14637 log.cc:1079] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/14bd1f57cdc942ceb6d4b1e4ce4b2094/wal-000000025 (ops 119-123)
I20260812 06:19:16.733045 14637 log.cc:1079] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/14bd1f57cdc942ceb6d4b1e4ce4b2094/wal-000000026 (ops 124-128)
I20260812 06:19:16.733076 14637 log.cc:1079] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/14bd1f57cdc942ceb6d4b1e4ce4b2094/wal-000000027 (ops 129-132)
I20260812 06:19:16.757073 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: LogGCOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.024s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:19:16.757705 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling UndoDeltaBlockGCOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): 483 bytes on disk
I20260812 06:19:16.758180 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: UndoDeltaBlockGCOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:19:16.758810 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=3.181125
I20260812 06:19:16.778877 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.020s	user 0.007s	sys 0.011s Metrics: {"bytes_written":5128262,"delete_count":0,"lbm_write_time_us":5011,"lbm_writes_lt_1ms":128,"reinsert_count":0,"update_count":625}
I20260812 06:19:16.779417 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=1.196750
I20260812 06:19:16.787554 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.008s	user 0.003s	sys 0.004s Metrics: {"bytes_written":3077030,"delete_count":0,"lbm_write_time_us":2865,"lbm_writes_lt_1ms":78,"reinsert_count":0,"update_count":375}
I20260812 06:19:16.788059 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling MajorDeltaCompactionOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=1.000000
I20260812 06:19:16.976559 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: MajorDeltaCompactionOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.188s	user 0.122s	sys 0.061s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":961,"lbm_read_time_us":12541,"lbm_reads_lt_1ms":674,"lbm_write_time_us":29988,"lbm_writes_lt_1ms":643,"mutex_wait_us":308,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":107,"threads_started":1,"update_count":3000}
I20260812 06:19:16.977375 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=14.095187
I20260812 06:19:17.043434 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.066s	user 0.018s	sys 0.046s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26360,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:17.044100 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=2.188937
I20260812 06:19:17.055752 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4508,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:17.056433 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling MajorDeltaCompactionOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=1.000000
I20260812 06:19:17.236182 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: MajorDeltaCompactionOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.180s	user 0.127s	sys 0.052s 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":543,"lbm_read_time_us":11623,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30262,"lbm_writes_lt_1ms":543,"mutex_wait_us":307,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17024,"update_count":2500}
I20260812 06:19:17.236820 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=10.126437
I20260812 06:19:17.276404 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.039s	user 0.028s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17307,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:17.277675 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=2.188937
I20260812 06:19:17.302526 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.025s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5142,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:17.303037 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=2.188937
I20260812 06:19:17.325701 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.022s	user 0.011s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5289,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:17.326344 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling MajorDeltaCompactionOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=1.000000
I20260812 06:19:17.482244 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: MajorDeltaCompactionOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.156s	user 0.107s	sys 0.048s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774809,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":492,"lbm_read_time_us":11809,"lbm_reads_lt_1ms":573,"lbm_write_time_us":24483,"lbm_writes_lt_1ms":543,"mutex_wait_us":222,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2500}
I20260812 06:19:17.482839 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=10.126437
I20260812 06:19:17.522864 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.040s	user 0.031s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14536,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:17.523420 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=2.188937
I20260812 06:19:17.548059 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.024s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5277,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:17.548655 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=2.188937
I20260812 06:19:17.559082 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3780,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:17.559813 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling MajorDeltaCompactionOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=1.000000
I20260812 06:19:17.726267 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: MajorDeltaCompactionOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.166s	user 0.122s	sys 0.039s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774808,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":854,"lbm_read_time_us":9556,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30180,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:17.726963 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=11.118625
I20260812 06:19:17.759506 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.032s	user 0.011s	sys 0.019s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12642,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:17.760064 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=2.188937
I20260812 06:19:17.786929 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.027s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3774459,"delete_count":0,"lbm_write_time_us":5233,"lbm_writes_lt_1ms":95,"reinsert_count":0,"update_count":460}
I20260812 06:19:17.787464 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=2.188937
I20260812 06:19:17.798869 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4020609,"delete_count":0,"lbm_write_time_us":4286,"lbm_writes_lt_1ms":101,"reinsert_count":0,"update_count":490}
I20260812 06:19:17.799374 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling MajorDeltaCompactionOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=1.000000
I20260812 06:19:17.953198 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: MajorDeltaCompactionOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.154s	user 0.116s	sys 0.026s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774803,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":807,"lbm_read_time_us":8796,"lbm_reads_lt_1ms":565,"lbm_write_time_us":28031,"lbm_writes_lt_1ms":543,"mutex_wait_us":44,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":2500}
I20260812 06:19:17.953776 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=14.095187
I20260812 06:19:17.999162 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.045s	user 0.026s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":16637,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:17.999671 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=2.188937
I20260812 06:19:18.015599 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6014,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:18.016198 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling MajorDeltaCompactionOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=1.000000
I20260812 06:19:18.166512 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: MajorDeltaCompactionOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.150s	user 0.083s	sys 0.066s 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":790,"lbm_read_time_us":10986,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28475,"lbm_writes_lt_1ms":543,"mutex_wait_us":264,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2500}
I20260812 06:19:18.167133 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=11.118625
I20260812 06:19:18.207484 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.040s	user 0.018s	sys 0.020s Metrics: {"bytes_written":12717738,"delete_count":0,"lbm_write_time_us":15748,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:19:18.208258 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=2.188937
I20260812 06:19:18.222430 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4786,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:18.223153 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushMRSOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=1.000000
I20260812 06:19:18.261142 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushMRSOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.038s	user 0.024s	sys 0.003s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":45,"dirs.run_cpu_time_us":126,"dirs.run_wall_time_us":1125,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1822,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:18.261875 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling UndoDeltaBlockGCOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): 492 bytes on disk
I20260812 06:19:18.262332 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: UndoDeltaBlockGCOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4}
I20260812 06:19:18.262825 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=3.181125
I20260812 06:19:18.274700 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":3865,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:18.275179 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling LogGCOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): free 129773852 bytes of WAL
I20260812 06:19:18.275388 14637 log_reader.cc:385] T 14bd1f57cdc942ceb6d4b1e4ce4b2094: removed 13 log segments from log reader
I20260812 06:19:18.275432 14637 log.cc:1079] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/14bd1f57cdc942ceb6d4b1e4ce4b2094/wal-000000028 (ops 133-137)
I20260812 06:19:18.275462 14637 log.cc:1079] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/14bd1f57cdc942ceb6d4b1e4ce4b2094/wal-000000029 (ops 138-142)
I20260812 06:19:18.275493 14637 log.cc:1079] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/14bd1f57cdc942ceb6d4b1e4ce4b2094/wal-000000030 (ops 143-147)
I20260812 06:19:18.275527 14637 log.cc:1079] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/14bd1f57cdc942ceb6d4b1e4ce4b2094/wal-000000031 (ops 148-152)
I20260812 06:19:18.275557 14637 log.cc:1079] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/14bd1f57cdc942ceb6d4b1e4ce4b2094/wal-000000032 (ops 153-157)
I20260812 06:19:18.275589 14637 log.cc:1079] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/14bd1f57cdc942ceb6d4b1e4ce4b2094/wal-000000033 (ops 158-162)
I20260812 06:19:18.275622 14637 log.cc:1079] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/14bd1f57cdc942ceb6d4b1e4ce4b2094/wal-000000034 (ops 163-167)
I20260812 06:19:18.275652 14637 log.cc:1079] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/14bd1f57cdc942ceb6d4b1e4ce4b2094/wal-000000035 (ops 168-172)
I20260812 06:19:18.275683 14637 log.cc:1079] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/14bd1f57cdc942ceb6d4b1e4ce4b2094/wal-000000036 (ops 173-177)
I20260812 06:19:18.275714 14637 log.cc:1079] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/14bd1f57cdc942ceb6d4b1e4ce4b2094/wal-000000037 (ops 178-182)
I20260812 06:19:18.275745 14637 log.cc:1079] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/14bd1f57cdc942ceb6d4b1e4ce4b2094/wal-000000038 (ops 183-186)
I20260812 06:19:18.275777 14637 log.cc:1079] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/14bd1f57cdc942ceb6d4b1e4ce4b2094/wal-000000039 (ops 187-191)
I20260812 06:19:18.275807 14637 log.cc:1079] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/14bd1f57cdc942ceb6d4b1e4ce4b2094/wal-000000040 (ops 192-196)
I20260812 06:19:18.297986 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: LogGCOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.023s	user 0.003s	sys 0.018s Metrics: {}
I20260812 06:19:18.298377 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=2.188937
I20260812 06:19:18.313717 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.015s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3995,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:18.314208 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=2.188937
I20260812 06:19:18.328142 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: FlushDeltaMemStoresOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.014s	user 0.008s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5193,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:18.328714 14715 maintenance_manager.cc:419] P 45c4d23907da449cbe2d8ed56dd534d4: Scheduling MajorDeltaCompactionOp(14bd1f57cdc942ceb6d4b1e4ce4b2094): perf score=1.000000
I20260812 06:19:18.358820 14519 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.635s	user 1.665s	sys 0.160s
I20260812 06:19:18.458108 14519 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.099s	user 0.003s	sys 0.000s
I20260812 06:19:18.458755 14519 tablet_server.cc:179] TabletServer@127.14.45.193:0 shutting down...
I20260812 06:19:18.497836 14637 maintenance_manager.cc:643] P 45c4d23907da449cbe2d8ed56dd534d4: MajorDeltaCompactionOp(14bd1f57cdc942ceb6d4b1e4ce4b2094) complete. Timing: real 0.169s	user 0.129s	sys 0.040s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979850,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":566,"lbm_read_time_us":12719,"lbm_reads_lt_1ms":771,"lbm_write_time_us":31189,"lbm_writes_lt_1ms":743,"mutex_wait_us":63,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":28032,"thread_start_us":75,"threads_started":1,"update_count":3500}
I20260812 06:19:18.499204 14519 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:18.499724 14519 tablet_replica.cc:333] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4: stopping tablet replica
I20260812 06:19:18.499992 14519 raft_consensus.cc:2243] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:18.500231 14519 raft_consensus.cc:2272] T 14bd1f57cdc942ceb6d4b1e4ce4b2094 P 45c4d23907da449cbe2d8ed56dd534d4 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:18.516595 14519 tablet_server.cc:196] TabletServer@127.14.45.193:0 shutdown complete.
I20260812 06:19:18.555199 14519 master.cc:562] Master@127.14.45.254:41351 shutting down...
I20260812 06:19:18.558403 14519 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 4ba0629ce63d4c76a764cb2d3d865f02 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:18.558570 14519 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 4ba0629ce63d4c76a764cb2d3d865f02 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:18.558645 14519 tablet_replica.cc:333] T 00000000000000000000000000000000 P 4ba0629ce63d4c76a764cb2d3d865f02: stopping tablet replica
I20260812 06:19:18.570827 14519 master.cc:584] Master@127.14.45.254:41351 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5201 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:18.639355 14519 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.14.45.254:34477
I20260812 06:19:18.639739 14519 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:18.641752 14752 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:18.641752 14751 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:18.641832 14519 server_base.cc:1061] running on GCE node
W20260812 06:19:18.641773 14754 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:18.642143 14519 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:18.642187 14519 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:18.642207 14519 hybrid_clock.cc:648] HybridClock initialized: now 1786515558642207 us; error 0 us; skew 500 ppm
I20260812 06:19:18.643079 14519 webserver.cc:533] Webserver started at http://127.14.45.254:36449/ using document root <none> and password file <none>
I20260812 06:19:18.643235 14519 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:18.643286 14519 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:18.643363 14519 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:18.643748 14519 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/master-0-root/instance:
uuid: "19ba80d63b2e44268fa99e64fe322d72"
format_stamp: "Formatted at 2026-08-12 06:19:18 on dist-test-slave-vq2q"
I20260812 06:19:18.645148 14519 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:18.646073 14761 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:18.646301 14519 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:18.646373 14519 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/master-0-root
uuid: "19ba80d63b2e44268fa99e64fe322d72"
format_stamp: "Formatted at 2026-08-12 06:19:18 on dist-test-slave-vq2q"
I20260812 06:19:18.646450 14519 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:18.670342 14519 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:18.670760 14519 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:18.674862 14519 rpc_server.cc:307] RPC server started. Bound to: 127.14.45.254:34477
I20260812 06:19:18.690603 14824 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:18.690627 14822 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.14.45.254:34477 every 8 connection(s)
I20260812 06:19:18.692605 14824 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 19ba80d63b2e44268fa99e64fe322d72: Bootstrap starting.
I20260812 06:19:18.693446 14824 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 19ba80d63b2e44268fa99e64fe322d72: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:18.694484 14824 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 19ba80d63b2e44268fa99e64fe322d72: No bootstrap required, opened a new log
I20260812 06:19:18.694873 14824 raft_consensus.cc:359] T 00000000000000000000000000000000 P 19ba80d63b2e44268fa99e64fe322d72 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "19ba80d63b2e44268fa99e64fe322d72" member_type: VOTER }
I20260812 06:19:18.694962 14824 raft_consensus.cc:385] T 00000000000000000000000000000000 P 19ba80d63b2e44268fa99e64fe322d72 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:18.694993 14824 raft_consensus.cc:740] T 00000000000000000000000000000000 P 19ba80d63b2e44268fa99e64fe322d72 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 19ba80d63b2e44268fa99e64fe322d72, State: Initialized, Role: FOLLOWER
I20260812 06:19:18.695144 14824 consensus_queue.cc:260] T 00000000000000000000000000000000 P 19ba80d63b2e44268fa99e64fe322d72 [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: "19ba80d63b2e44268fa99e64fe322d72" member_type: VOTER }
I20260812 06:19:18.695231 14824 raft_consensus.cc:399] T 00000000000000000000000000000000 P 19ba80d63b2e44268fa99e64fe322d72 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:18.695271 14824 raft_consensus.cc:493] T 00000000000000000000000000000000 P 19ba80d63b2e44268fa99e64fe322d72 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:18.695319 14824 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 19ba80d63b2e44268fa99e64fe322d72 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:18.695989 14824 raft_consensus.cc:515] T 00000000000000000000000000000000 P 19ba80d63b2e44268fa99e64fe322d72 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "19ba80d63b2e44268fa99e64fe322d72" member_type: VOTER }
I20260812 06:19:18.696103 14824 leader_election.cc:304] T 00000000000000000000000000000000 P 19ba80d63b2e44268fa99e64fe322d72 [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: 19ba80d63b2e44268fa99e64fe322d72; no voters: 
I20260812 06:19:18.696275 14824 leader_election.cc:290] T 00000000000000000000000000000000 P 19ba80d63b2e44268fa99e64fe322d72 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:18.696426 14831 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 19ba80d63b2e44268fa99e64fe322d72 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:18.696616 14831 raft_consensus.cc:697] T 00000000000000000000000000000000 P 19ba80d63b2e44268fa99e64fe322d72 [term 1 LEADER]: Becoming Leader. State: Replica: 19ba80d63b2e44268fa99e64fe322d72, State: Running, Role: LEADER
I20260812 06:19:18.696719 14824 sys_catalog.cc:565] T 00000000000000000000000000000000 P 19ba80d63b2e44268fa99e64fe322d72 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:18.696758 14831 consensus_queue.cc:237] T 00000000000000000000000000000000 P 19ba80d63b2e44268fa99e64fe322d72 [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: "19ba80d63b2e44268fa99e64fe322d72" member_type: VOTER }
I20260812 06:19:18.697244 14833 sys_catalog.cc:455] T 00000000000000000000000000000000 P 19ba80d63b2e44268fa99e64fe322d72 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "19ba80d63b2e44268fa99e64fe322d72" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "19ba80d63b2e44268fa99e64fe322d72" member_type: VOTER } }
I20260812 06:19:18.697273 14834 sys_catalog.cc:455] T 00000000000000000000000000000000 P 19ba80d63b2e44268fa99e64fe322d72 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 19ba80d63b2e44268fa99e64fe322d72. Latest consensus state: current_term: 1 leader_uuid: "19ba80d63b2e44268fa99e64fe322d72" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "19ba80d63b2e44268fa99e64fe322d72" member_type: VOTER } }
I20260812 06:19:18.697335 14833 sys_catalog.cc:458] T 00000000000000000000000000000000 P 19ba80d63b2e44268fa99e64fe322d72 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:18.697360 14834 sys_catalog.cc:458] T 00000000000000000000000000000000 P 19ba80d63b2e44268fa99e64fe322d72 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:18.697578 14837 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:18.698345 14837 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:18.698590 14519 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:18.700034 14837 catalog_manager.cc:1383] Generated new cluster ID: 9dd442b68d4d4a899d9c0bccfc6cd6f5
I20260812 06:19:18.700091 14837 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:18.721112 14837 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:18.721666 14837 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:18.727089 14837 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 19ba80d63b2e44268fa99e64fe322d72: Generated new TSK 0
I20260812 06:19:18.727238 14837 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:18.730798 14519 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:18.732631 14851 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:18.732659 14519 server_base.cc:1061] running on GCE node
W20260812 06:19:18.732630 14855 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:18.732764 14852 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:18.733021 14519 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:18.733062 14519 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:18.733081 14519 hybrid_clock.cc:648] HybridClock initialized: now 1786515558733082 us; error 0 us; skew 500 ppm
I20260812 06:19:18.733897 14519 webserver.cc:533] Webserver started at http://127.14.45.193:44411/ using document root <none> and password file <none>
I20260812 06:19:18.734032 14519 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:18.734076 14519 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:18.734129 14519 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:18.734483 14519 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root/instance:
uuid: "4075900b91154183b8968fcf01ea7845"
format_stamp: "Formatted at 2026-08-12 06:19:18 on dist-test-slave-vq2q"
I20260812 06:19:18.735878 14519 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:18.736747 14860 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:18.736953 14519 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:18.737022 14519 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root
uuid: "4075900b91154183b8968fcf01ea7845"
format_stamp: "Formatted at 2026-08-12 06:19:18 on dist-test-slave-vq2q"
I20260812 06:19:18.737087 14519 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:18.748064 14519 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:18.748411 14519 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:18.748694 14519 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:18.749150 14519 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:18.749225 14519 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:18.749292 14519 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:18.749320 14519 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:18.753327 14519 rpc_server.cc:307] RPC server started. Bound to: 127.14.45.193:45433
I20260812 06:19:18.753353 14931 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.14.45.193:45433 every 8 connection(s)
I20260812 06:19:18.760563 14933 heartbeater.cc:344] Connected to a master server at 127.14.45.254:34477
I20260812 06:19:18.760665 14933 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:18.760878 14933 heartbeater.cc:507] Master 127.14.45.254:34477 requested a full tablet report, sending...
I20260812 06:19:18.761515 14779 ts_manager.cc:194] Registered new tserver with Master: 4075900b91154183b8968fcf01ea7845 (127.14.45.193:45433)
I20260812 06:19:18.761567 14519 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.007845838s
I20260812 06:19:18.762283 14779 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:45368
I20260812 06:19:18.767970 14779 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:45384:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:18.776119 14891 tablet_service.cc:1511] Processing CreateTablet for tablet cd6e08127c7649a7b09bcef074e07554 (DEFAULT_TABLE table=heavy-update-compaction-test [id=dadc42ddae3e47c783505d5670aa99f7]), partition=
I20260812 06:19:18.776372 14891 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet cd6e08127c7649a7b09bcef074e07554. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:18.778278 14949 tablet_bootstrap.cc:492] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Bootstrap starting.
I20260812 06:19:18.779196 14949 tablet_bootstrap.cc:654] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:18.780256 14949 tablet_bootstrap.cc:492] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: No bootstrap required, opened a new log
I20260812 06:19:18.780331 14949 ts_tablet_manager.cc:1403] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:18.780740 14949 raft_consensus.cc:359] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4075900b91154183b8968fcf01ea7845" member_type: VOTER last_known_addr { host: "127.14.45.193" port: 45433 } }
I20260812 06:19:18.780827 14949 raft_consensus.cc:385] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:18.780849 14949 raft_consensus.cc:740] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4075900b91154183b8968fcf01ea7845, State: Initialized, Role: FOLLOWER
I20260812 06:19:18.780985 14949 consensus_queue.cc:260] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845 [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: "4075900b91154183b8968fcf01ea7845" member_type: VOTER last_known_addr { host: "127.14.45.193" port: 45433 } }
I20260812 06:19:18.781055 14949 raft_consensus.cc:399] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:18.781087 14949 raft_consensus.cc:493] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:18.781136 14949 raft_consensus.cc:3060] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:18.781860 14949 raft_consensus.cc:515] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4075900b91154183b8968fcf01ea7845" member_type: VOTER last_known_addr { host: "127.14.45.193" port: 45433 } }
I20260812 06:19:18.781996 14949 leader_election.cc:304] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845 [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: 4075900b91154183b8968fcf01ea7845; no voters: 
I20260812 06:19:18.782166 14949 leader_election.cc:290] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:18.782276 14952 raft_consensus.cc:2804] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:18.782462 14949 ts_tablet_manager.cc:1434] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:18.782490 14952 raft_consensus.cc:697] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845 [term 1 LEADER]: Becoming Leader. State: Replica: 4075900b91154183b8968fcf01ea7845, State: Running, Role: LEADER
I20260812 06:19:18.782549 14933 heartbeater.cc:499] Master 127.14.45.254:34477 was elected leader, sending a full tablet report...
I20260812 06:19:18.782655 14952 consensus_queue.cc:237] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845 [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: "4075900b91154183b8968fcf01ea7845" member_type: VOTER last_known_addr { host: "127.14.45.193" port: 45433 } }
I20260812 06:19:18.783941 14779 catalog_manager.cc:5719] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845 reported cstate change: term changed from 0 to 1, leader changed from <none> to 4075900b91154183b8968fcf01ea7845 (127.14.45.193). New cstate: current_term: 1 leader_uuid: "4075900b91154183b8968fcf01ea7845" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4075900b91154183b8968fcf01ea7845" member_type: VOTER last_known_addr { host: "127.14.45.193" port: 45433 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:18.840368 14519 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.012s	sys 0.010s
I20260812 06:19:19.004218 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushMRSOp(cd6e08127c7649a7b09bcef074e07554): perf score=19.054940
I20260812 06:19:19.156458 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushMRSOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.152s	user 0.108s	sys 0.039s Metrics: {"bytes_written":12676712,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":221,"dirs.run_wall_time_us":799,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":36141,"lbm_writes_lt_1ms":776,"mutex_wait_us":1492,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1545}
I20260812 06:19:19.157078 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling LogGCOp(cd6e08127c7649a7b09bcef074e07554): free 20743880 bytes of WAL
I20260812 06:19:19.157341 14867 log_reader.cc:385] T cd6e08127c7649a7b09bcef074e07554: removed 2 log segments from log reader
I20260812 06:19:19.157392 14867 log.cc:1079] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/cd6e08127c7649a7b09bcef074e07554/wal-000000001 (ops 1-6)
I20260812 06:19:19.157433 14867 log.cc:1079] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/cd6e08127c7649a7b09bcef074e07554/wal-000000002 (ops 7-11)
I20260812 06:19:19.162213 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: LogGCOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.005s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:19:19.162607 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=2.188937
I20260812 06:19:19.178300 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.016s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3733434,"delete_count":0,"lbm_write_time_us":3261,"lbm_writes_lt_1ms":94,"reinsert_count":0,"update_count":455}
I20260812 06:19:19.178743 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling UndoDeltaBlockGCOp(cd6e08127c7649a7b09bcef074e07554): 16821653 bytes on disk
I20260812 06:19:19.179157 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: UndoDeltaBlockGCOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:19:19.179594 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=2.188937
I20260812 06:19:19.188745 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3277,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:19.189211 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling MajorDeltaCompactionOp(cd6e08127c7649a7b09bcef074e07554): perf score=1.000000
I20260812 06:19:19.349490 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: MajorDeltaCompactionOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.160s	user 0.109s	sys 0.041s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24405546,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":550,"lbm_read_time_us":11922,"lbm_reads_lt_1ms":559,"lbm_write_time_us":25672,"lbm_writes_lt_1ms":533,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":5248,"thread_start_us":293,"threads_started":5,"update_count":2450}
I20260812 06:19:19.350054 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=14.095187
I20260812 06:19:19.393764 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.044s	user 0.032s	sys 0.007s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":17121,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:19.394249 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=2.188937
I20260812 06:19:19.404229 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3636,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:19.404821 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling MajorDeltaCompactionOp(cd6e08127c7649a7b09bcef074e07554): perf score=1.000000
I20260812 06:19:19.547811 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: MajorDeltaCompactionOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.143s	user 0.103s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":519,"lbm_read_time_us":8870,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27757,"lbm_writes_lt_1ms":543,"mutex_wait_us":259,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8192,"update_count":2500}
I20260812 06:19:19.548337 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=11.118625
I20260812 06:19:19.584182 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.036s	user 0.017s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15443,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:19.584683 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=2.188937
I20260812 06:19:19.599136 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4947,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:19.599668 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling MajorDeltaCompactionOp(cd6e08127c7649a7b09bcef074e07554): perf score=1.000000
I20260812 06:19:19.781693 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: MajorDeltaCompactionOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.182s	user 0.133s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":789,"lbm_read_time_us":10212,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29250,"lbm_writes_lt_1ms":443,"mutex_wait_us":451,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:19:19.783258 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=11.118625
I20260812 06:19:19.895808 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.112s	user 0.053s	sys 0.052s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":47273,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:19:19.897159 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=2.188937
I20260812 06:19:19.953994 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.056s	user 0.013s	sys 0.017s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":11522,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:19.955183 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=2.188937
I20260812 06:19:19.997634 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.042s	user 0.018s	sys 0.023s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":10408,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:19.999027 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling MajorDeltaCompactionOp(cd6e08127c7649a7b09bcef074e07554): perf score=1.000000
I20260812 06:19:20.527263 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: MajorDeltaCompactionOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.528s	user 0.353s	sys 0.167s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815795,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":317,"lbm_read_time_us":30826,"lbm_reads_1-10_ms":4,"lbm_reads_lt_1ms":569,"lbm_write_time_us":99303,"lbm_writes_1-10_ms":4,"lbm_writes_lt_1ms":539,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11520,"thread_start_us":343,"threads_started":6,"update_count":2500}
I20260812 06:19:20.527803 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=14.095187
I20260812 06:19:20.577147 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.049s	user 0.031s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23100,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:20.577773 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=2.188937
I20260812 06:19:20.588527 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.011s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3875,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:20.589000 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling MajorDeltaCompactionOp(cd6e08127c7649a7b09bcef074e07554): perf score=1.000000
I20260812 06:19:20.757542 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: MajorDeltaCompactionOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.168s	user 0.112s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":825,"lbm_read_time_us":9299,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27669,"lbm_writes_lt_1ms":543,"mutex_wait_us":314,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:20.758090 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=14.095187
I20260812 06:19:20.813802 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.056s	user 0.031s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20429,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:20.814359 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=2.188937
I20260812 06:19:20.825675 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3966,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:20.826188 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushMRSOp(cd6e08127c7649a7b09bcef074e07554): perf score=1.000000
I20260812 06:19:20.856437 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushMRSOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.030s	user 0.027s	sys 0.001s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":88,"dirs.run_cpu_time_us":276,"dirs.run_wall_time_us":1489,"drs_written":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1970,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:20.857127 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling LogGCOp(cd6e08127c7649a7b09bcef074e07554): free 120553322 bytes of WAL
I20260812 06:19:20.857432 14867 log_reader.cc:385] T cd6e08127c7649a7b09bcef074e07554: removed 12 log segments from log reader
I20260812 06:19:20.857481 14867 log.cc:1079] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/cd6e08127c7649a7b09bcef074e07554/wal-000000003 (ops 12-16)
I20260812 06:19:20.857511 14867 log.cc:1079] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/cd6e08127c7649a7b09bcef074e07554/wal-000000004 (ops 17-21)
I20260812 06:19:20.857532 14867 log.cc:1079] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/cd6e08127c7649a7b09bcef074e07554/wal-000000005 (ops 22-26)
I20260812 06:19:20.857563 14867 log.cc:1079] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/cd6e08127c7649a7b09bcef074e07554/wal-000000006 (ops 27-30)
I20260812 06:19:20.857583 14867 log.cc:1079] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/cd6e08127c7649a7b09bcef074e07554/wal-000000007 (ops 31-35)
I20260812 06:19:20.857614 14867 log.cc:1079] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/cd6e08127c7649a7b09bcef074e07554/wal-000000008 (ops 36-40)
I20260812 06:19:20.857645 14867 log.cc:1079] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/cd6e08127c7649a7b09bcef074e07554/wal-000000009 (ops 41-45)
I20260812 06:19:20.857694 14867 log.cc:1079] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/cd6e08127c7649a7b09bcef074e07554/wal-000000010 (ops 46-50)
I20260812 06:19:20.857728 14867 log.cc:1079] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/cd6e08127c7649a7b09bcef074e07554/wal-000000011 (ops 51-54)
I20260812 06:19:20.857758 14867 log.cc:1079] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/cd6e08127c7649a7b09bcef074e07554/wal-000000012 (ops 55-59)
I20260812 06:19:20.857790 14867 log.cc:1079] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/cd6e08127c7649a7b09bcef074e07554/wal-000000013 (ops 60-64)
I20260812 06:19:20.857820 14867 log.cc:1079] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/cd6e08127c7649a7b09bcef074e07554/wal-000000014 (ops 65-69)
I20260812 06:19:20.878859 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: LogGCOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.021s	user 0.004s	sys 0.016s Metrics: {}
I20260812 06:19:20.879338 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling UndoDeltaBlockGCOp(cd6e08127c7649a7b09bcef074e07554): 448 bytes on disk
I20260812 06:19:20.879799 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: UndoDeltaBlockGCOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:19:20.880296 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=3.181125
I20260812 06:19:20.904524 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.024s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":4236,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:20.905016 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=2.188937
I20260812 06:19:20.915432 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.010s	user 0.000s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3788,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:20.915913 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling MajorDeltaCompactionOp(cd6e08127c7649a7b09bcef074e07554): perf score=1.000000
I20260812 06:19:21.155304 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: MajorDeltaCompactionOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.239s	user 0.131s	sys 0.097s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020733,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":831,"lbm_read_time_us":16889,"lbm_reads_lt_1ms":774,"lbm_write_time_us":34517,"lbm_writes_lt_1ms":743,"mutex_wait_us":316,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":6912,"thread_start_us":147,"threads_started":1,"update_count":3500}
I20260812 06:19:21.155926 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=18.063937
I20260812 06:19:21.207480 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.051s	user 0.017s	sys 0.032s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":23417,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:21.207955 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling MajorDeltaCompactionOp(cd6e08127c7649a7b09bcef074e07554): perf score=1.000000
I20260812 06:19:21.371766 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: MajorDeltaCompactionOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.164s	user 0.096s	sys 0.068s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24815567,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":171,"lbm_read_time_us":11482,"lbm_reads_lt_1ms":563,"lbm_write_time_us":27378,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":2500}
I20260812 06:19:21.372303 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=14.095187
I20260812 06:19:21.418406 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.046s	user 0.014s	sys 0.031s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":15763,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:21.419001 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=2.188937
I20260812 06:19:21.445456 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.026s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4225732,"delete_count":0,"lbm_write_time_us":4639,"lbm_writes_lt_1ms":106,"mutex_wait_us":63,"reinsert_count":0,"update_count":515}
I20260812 06:19:21.445926 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=2.188937
I20260812 06:19:21.455837 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":3979584,"delete_count":0,"lbm_write_time_us":3639,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:19:21.456305 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling MajorDeltaCompactionOp(cd6e08127c7649a7b09bcef074e07554): perf score=1.000000
I20260812 06:19:21.661202 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: MajorDeltaCompactionOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.205s	user 0.144s	sys 0.060s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918216,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1049,"lbm_read_time_us":13654,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33604,"lbm_writes_lt_1ms":643,"mutex_wait_us":338,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":3000}
I20260812 06:19:21.661734 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=14.095187
I20260812 06:19:21.707152 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.045s	user 0.019s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18031,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:21.708303 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling MajorDeltaCompactionOp(cd6e08127c7649a7b09bcef074e07554): perf score=1.000000
I20260812 06:19:21.861999 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: MajorDeltaCompactionOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.154s	user 0.102s	sys 0.043s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":843,"lbm_read_time_us":10220,"lbm_reads_lt_1ms":463,"lbm_write_time_us":22605,"lbm_writes_lt_1ms":443,"mutex_wait_us":297,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":2000}
I20260812 06:19:21.862521 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=14.095187
I20260812 06:19:21.933080 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.070s	user 0.031s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":44774,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:21.933554 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=2.188937
I20260812 06:19:21.956104 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.022s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4640,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:21.956629 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling MajorDeltaCompactionOp(cd6e08127c7649a7b09bcef074e07554): perf score=1.000000
I20260812 06:19:22.125999 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: MajorDeltaCompactionOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.169s	user 0.101s	sys 0.067s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":503,"lbm_read_time_us":10920,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28006,"lbm_writes_lt_1ms":543,"mutex_wait_us":287,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17920,"update_count":2500}
I20260812 06:19:22.126621 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=14.095187
I20260812 06:19:22.171701 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.045s	user 0.014s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17654,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:22.172312 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=2.188937
I20260812 06:19:22.192304 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.020s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4202,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:22.192786 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=2.188937
I20260812 06:19:22.207911 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5359,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:22.208536 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushMRSOp(cd6e08127c7649a7b09bcef074e07554): perf score=1.000000
I20260812 06:19:22.249169 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushMRSOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.040s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":150,"dirs.run_wall_time_us":1166,"drs_written":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2156,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:22.249897 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling LogGCOp(cd6e08127c7649a7b09bcef074e07554): free 112239324 bytes of WAL
I20260812 06:19:22.250124 14867 log_reader.cc:385] T cd6e08127c7649a7b09bcef074e07554: removed 11 log segments from log reader
I20260812 06:19:22.250168 14867 log.cc:1079] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/cd6e08127c7649a7b09bcef074e07554/wal-000000015 (ops 70-74)
I20260812 06:19:22.250200 14867 log.cc:1079] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/cd6e08127c7649a7b09bcef074e07554/wal-000000016 (ops 75-79)
I20260812 06:19:22.250229 14867 log.cc:1079] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/cd6e08127c7649a7b09bcef074e07554/wal-000000017 (ops 80-84)
I20260812 06:19:22.250262 14867 log.cc:1079] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/cd6e08127c7649a7b09bcef074e07554/wal-000000018 (ops 85-89)
I20260812 06:19:22.250285 14867 log.cc:1079] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/cd6e08127c7649a7b09bcef074e07554/wal-000000019 (ops 90-94)
I20260812 06:19:22.250317 14867 log.cc:1079] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/cd6e08127c7649a7b09bcef074e07554/wal-000000020 (ops 95-98)
I20260812 06:19:22.250350 14867 log.cc:1079] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/cd6e08127c7649a7b09bcef074e07554/wal-000000021 (ops 99-103)
I20260812 06:19:22.250381 14867 log.cc:1079] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/cd6e08127c7649a7b09bcef074e07554/wal-000000022 (ops 104-108)
I20260812 06:19:22.250413 14867 log.cc:1079] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/cd6e08127c7649a7b09bcef074e07554/wal-000000023 (ops 109-113)
I20260812 06:19:22.250453 14867 log.cc:1079] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/cd6e08127c7649a7b09bcef074e07554/wal-000000024 (ops 114-118)
I20260812 06:19:22.250483 14867 log.cc:1079] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/cd6e08127c7649a7b09bcef074e07554/wal-000000025 (ops 119-123)
I20260812 06:19:22.268978 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: LogGCOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.019s	user 0.001s	sys 0.014s Metrics: {}
I20260812 06:19:22.269410 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=2.188937
I20260812 06:19:22.295349 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.026s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4012,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:22.295805 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling UndoDeltaBlockGCOp(cd6e08127c7649a7b09bcef074e07554): 447 bytes on disk
I20260812 06:19:22.296195 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: UndoDeltaBlockGCOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:19:22.296684 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=2.188937
I20260812 06:19:22.306696 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3690,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:22.307242 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling MajorDeltaCompactionOp(cd6e08127c7649a7b09bcef074e07554): perf score=1.000000
I20260812 06:19:22.548688 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: MajorDeltaCompactionOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.241s	user 0.158s	sys 0.081s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37123276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":4388,"lbm_read_time_us":17234,"lbm_reads_lt_1ms":875,"lbm_write_time_us":39979,"lbm_writes_lt_1ms":843,"mutex_wait_us":2271,"peak_mem_usage":100395616,"reinsert_count":0,"thread_start_us":76,"threads_started":1,"update_count":4000}
I20260812 06:19:22.549304 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=19.056125
I20260812 06:19:22.603003 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.054s	user 0.023s	sys 0.028s Metrics: {"bytes_written":20922552,"delete_count":0,"lbm_write_time_us":23411,"lbm_writes_lt_1ms":513,"reinsert_count":0,"update_count":2550}
I20260812 06:19:22.603515 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=2.188937
I20260812 06:19:22.628540 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.025s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3774459,"delete_count":0,"lbm_write_time_us":5073,"lbm_writes_lt_1ms":95,"reinsert_count":0,"update_count":460}
I20260812 06:19:22.629065 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=2.188937
I20260812 06:19:22.643966 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4020609,"delete_count":0,"lbm_write_time_us":5440,"lbm_writes_lt_1ms":101,"reinsert_count":0,"update_count":490}
I20260812 06:19:22.644559 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling MajorDeltaCompactionOp(cd6e08127c7649a7b09bcef074e07554): perf score=1.000000
I20260812 06:19:22.874403 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: MajorDeltaCompactionOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.230s	user 0.157s	sys 0.063s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":33020615,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":486,"lbm_read_time_us":15757,"lbm_reads_lt_1ms":773,"lbm_write_time_us":37093,"lbm_writes_lt_1ms":743,"mutex_wait_us":39,"peak_mem_usage":87969044,"reinsert_count":0,"update_count":3500}
I20260812 06:19:22.875150 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=18.063937
I20260812 06:19:22.934325 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.059s	user 0.026s	sys 0.031s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":25516,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:22.934852 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=2.188937
I20260812 06:19:22.947690 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.013s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4425,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:22.948231 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling MajorDeltaCompactionOp(cd6e08127c7649a7b09bcef074e07554): perf score=1.000000
I20260812 06:19:23.104488 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: MajorDeltaCompactionOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.156s	user 0.138s	sys 0.018s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918099,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":680,"lbm_read_time_us":10298,"lbm_reads_lt_1ms":664,"lbm_write_time_us":30993,"lbm_writes_lt_1ms":643,"mutex_wait_us":281,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":3000}
I20260812 06:19:23.105085 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=14.095187
I20260812 06:19:23.153218 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.048s	user 0.036s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21055,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:23.153746 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=2.188937
I20260812 06:19:23.166077 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3899,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:23.166596 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling MajorDeltaCompactionOp(cd6e08127c7649a7b09bcef074e07554): perf score=1.000000
I20260812 06:19:23.326892 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: MajorDeltaCompactionOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.160s	user 0.111s	sys 0.037s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":398,"lbm_read_time_us":9200,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27402,"lbm_writes_lt_1ms":543,"mutex_wait_us":60,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":116736,"update_count":2500}
I20260812 06:19:23.327607 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=14.095187
I20260812 06:19:23.374300 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.046s	user 0.025s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21113,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:23.374905 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling MajorDeltaCompactionOp(cd6e08127c7649a7b09bcef074e07554): perf score=1.000000
I20260812 06:19:23.526964 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: MajorDeltaCompactionOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.152s	user 0.085s	sys 0.056s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":294,"lbm_read_time_us":11578,"lbm_reads_lt_1ms":467,"lbm_write_time_us":22772,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:19:23.527609 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=14.095187
I20260812 06:19:23.575819 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.048s	user 0.020s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19645,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:23.576354 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=2.188937
I20260812 06:19:23.587271 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3957,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:23.587792 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushMRSOp(cd6e08127c7649a7b09bcef074e07554): perf score=1.000000
I20260812 06:19:23.619350 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushMRSOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.031s	user 0.027s	sys 0.003s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":51,"dirs.run_cpu_time_us":169,"dirs.run_wall_time_us":1338,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2097,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:23.620126 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling LogGCOp(cd6e08127c7649a7b09bcef074e07554): free 124710546 bytes of WAL
I20260812 06:19:23.620361 14867 log_reader.cc:385] T cd6e08127c7649a7b09bcef074e07554: removed 12 log segments from log reader
I20260812 06:19:23.620410 14867 log.cc:1079] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/cd6e08127c7649a7b09bcef074e07554/wal-000000026 (ops 124-128)
I20260812 06:19:23.620448 14867 log.cc:1079] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/cd6e08127c7649a7b09bcef074e07554/wal-000000027 (ops 129-133)
I20260812 06:19:23.620481 14867 log.cc:1079] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/cd6e08127c7649a7b09bcef074e07554/wal-000000028 (ops 134-138)
I20260812 06:19:23.620507 14867 log.cc:1079] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/cd6e08127c7649a7b09bcef074e07554/wal-000000029 (ops 139-143)
I20260812 06:19:23.620538 14867 log.cc:1079] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/cd6e08127c7649a7b09bcef074e07554/wal-000000030 (ops 144-148)
I20260812 06:19:23.620570 14867 log.cc:1079] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/cd6e08127c7649a7b09bcef074e07554/wal-000000031 (ops 149-153)
I20260812 06:19:23.620601 14867 log.cc:1079] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/cd6e08127c7649a7b09bcef074e07554/wal-000000032 (ops 154-158)
I20260812 06:19:23.620631 14867 log.cc:1079] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/cd6e08127c7649a7b09bcef074e07554/wal-000000033 (ops 159-163)
I20260812 06:19:23.620663 14867 log.cc:1079] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/cd6e08127c7649a7b09bcef074e07554/wal-000000034 (ops 164-168)
I20260812 06:19:23.620694 14867 log.cc:1079] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/cd6e08127c7649a7b09bcef074e07554/wal-000000035 (ops 169-173)
I20260812 06:19:23.620724 14867 log.cc:1079] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/cd6e08127c7649a7b09bcef074e07554/wal-000000036 (ops 174-178)
I20260812 06:19:23.620755 14867 log.cc:1079] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: Deleting log segment in path: /tmp/dist-test-taskY7BOWZ/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553426837-14519-0/minicluster-data/ts-0-root/wals/cd6e08127c7649a7b09bcef074e07554/wal-000000037 (ops 179-183)
I20260812 06:19:23.642678 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: LogGCOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.022s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:19:23.643267 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=2.188937
I20260812 06:19:23.666740 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.023s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5190,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:23.667233 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling UndoDeltaBlockGCOp(cd6e08127c7649a7b09bcef074e07554): 462 bytes on disk
I20260812 06:19:23.667680 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: UndoDeltaBlockGCOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:19:23.668272 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=2.188937
I20260812 06:19:23.683898 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5760,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:23.684419 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling MajorDeltaCompactionOp(cd6e08127c7649a7b09bcef074e07554): perf score=1.000000
I20260812 06:19:23.901675 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: MajorDeltaCompactionOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.217s	user 0.142s	sys 0.066s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020746,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1613,"lbm_read_time_us":13927,"lbm_reads_lt_1ms":774,"lbm_write_time_us":33469,"lbm_writes_lt_1ms":743,"mutex_wait_us":23,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":41344,"thread_start_us":82,"threads_started":1,"update_count":3500}
I20260812 06:19:23.902278 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=18.063937
I20260812 06:19:23.966995 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.065s	user 0.040s	sys 0.020s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":28658,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":501,"reinsert_count":0,"update_count":2500}
I20260812 06:19:23.967507 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554): perf score=2.188937
I20260812 06:19:23.982968 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: FlushDeltaMemStoresOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5598,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:23.983628 14934 maintenance_manager.cc:419] P 4075900b91154183b8968fcf01ea7845: Scheduling MajorDeltaCompactionOp(cd6e08127c7649a7b09bcef074e07554): perf score=1.000000
I20260812 06:19:24.058220 14519 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.218s	user 1.847s	sys 0.191s
I20260812 06:19:24.126807 14519 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.068s	user 0.001s	sys 0.000s
I20260812 06:19:24.127286 14519 tablet_server.cc:179] TabletServer@127.14.45.193:0 shutting down...
I20260812 06:19:24.144384 14867 maintenance_manager.cc:643] P 4075900b91154183b8968fcf01ea7845: MajorDeltaCompactionOp(cd6e08127c7649a7b09bcef074e07554) complete. Timing: real 0.161s	user 0.112s	sys 0.048s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918100,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":628,"lbm_read_time_us":12640,"lbm_reads_lt_1ms":668,"lbm_write_time_us":26153,"lbm_writes_lt_1ms":643,"mutex_wait_us":62,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:19:24.144946 14519 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:24.145205 14519 tablet_replica.cc:333] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845: stopping tablet replica
I20260812 06:19:24.145331 14519 raft_consensus.cc:2243] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:24.145491 14519 raft_consensus.cc:2272] T cd6e08127c7649a7b09bcef074e07554 P 4075900b91154183b8968fcf01ea7845 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:24.170138 14519 tablet_server.cc:196] TabletServer@127.14.45.193:0 shutdown complete.
I20260812 06:19:24.196105 14519 master.cc:562] Master@127.14.45.254:34477 shutting down...
I20260812 06:19:24.199198 14519 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 19ba80d63b2e44268fa99e64fe322d72 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:24.199397 14519 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 19ba80d63b2e44268fa99e64fe322d72 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:24.199468 14519 tablet_replica.cc:333] T 00000000000000000000000000000000 P 19ba80d63b2e44268fa99e64fe322d72: stopping tablet replica
I20260812 06:19:24.211696 14519 master.cc:584] Master@127.14.45.254:34477 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5643 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10846 ms total)

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