[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:18:58.837522  2475 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.2.106.254:45823
I20260812 06:18:58.838666  2475 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:18:58.839321  2475 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:58.846534  2487 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:58.846522  2483 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:58.846521  2484 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:58.846580  2475 server_base.cc:1061] running on GCE node
I20260812 06:18:58.847239  2475 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:58.847374  2475 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:58.847420  2475 hybrid_clock.cc:648] HybridClock initialized: now 1786515538847417 us; error 0 us; skew 500 ppm
I20260812 06:18:58.849232  2475 webserver.cc:533] Webserver started at http://127.2.106.254:39395/ using document root <none> and password file <none>
I20260812 06:18:58.849855  2475 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:58.849918  2475 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:58.850162  2475 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:58.851859  2475 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/master-0-root/instance:
uuid: "147bc78c9b644d87a66405abc4c0d001"
format_stamp: "Formatted at 2026-08-12 06:18:58 on dist-test-slave-7kzw"
I20260812 06:18:58.855285  2475 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.002s	sys 0.002s
I20260812 06:18:58.857259  2494 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:58.858289  2475 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.001s
I20260812 06:18:58.858412  2475 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/master-0-root
uuid: "147bc78c9b644d87a66405abc4c0d001"
format_stamp: "Formatted at 2026-08-12 06:18:58 on dist-test-slave-7kzw"
I20260812 06:18:58.858566  2475 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:58.880055  2475 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:58.880785  2475 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:18:58.880985  2475 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:58.889076  2475 rpc_server.cc:307] RPC server started. Bound to: 127.2.106.254:45823
I20260812 06:18:58.889083  2579 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.2.106.254:45823 every 8 connection(s)
I20260812 06:18:58.891723  2581 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:58.897666  2581 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 147bc78c9b644d87a66405abc4c0d001: Bootstrap starting.
I20260812 06:18:58.900360  2581 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 147bc78c9b644d87a66405abc4c0d001: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:58.901409  2581 log.cc:826] T 00000000000000000000000000000000 P 147bc78c9b644d87a66405abc4c0d001: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:58.903396  2581 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 147bc78c9b644d87a66405abc4c0d001: No bootstrap required, opened a new log
I20260812 06:18:58.906440  2581 raft_consensus.cc:359] T 00000000000000000000000000000000 P 147bc78c9b644d87a66405abc4c0d001 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "147bc78c9b644d87a66405abc4c0d001" member_type: VOTER }
I20260812 06:18:58.906698  2581 raft_consensus.cc:385] T 00000000000000000000000000000000 P 147bc78c9b644d87a66405abc4c0d001 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:58.906780  2581 raft_consensus.cc:740] T 00000000000000000000000000000000 P 147bc78c9b644d87a66405abc4c0d001 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 147bc78c9b644d87a66405abc4c0d001, State: Initialized, Role: FOLLOWER
I20260812 06:18:58.907482  2581 consensus_queue.cc:260] T 00000000000000000000000000000000 P 147bc78c9b644d87a66405abc4c0d001 [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: "147bc78c9b644d87a66405abc4c0d001" member_type: VOTER }
I20260812 06:18:58.907686  2581 raft_consensus.cc:399] T 00000000000000000000000000000000 P 147bc78c9b644d87a66405abc4c0d001 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:58.907776  2581 raft_consensus.cc:493] T 00000000000000000000000000000000 P 147bc78c9b644d87a66405abc4c0d001 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:58.907972  2581 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 147bc78c9b644d87a66405abc4c0d001 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:58.908874  2581 raft_consensus.cc:515] T 00000000000000000000000000000000 P 147bc78c9b644d87a66405abc4c0d001 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "147bc78c9b644d87a66405abc4c0d001" member_type: VOTER }
I20260812 06:18:58.909354  2581 leader_election.cc:304] T 00000000000000000000000000000000 P 147bc78c9b644d87a66405abc4c0d001 [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: 147bc78c9b644d87a66405abc4c0d001; no voters: 
I20260812 06:18:58.909730  2581 leader_election.cc:290] T 00000000000000000000000000000000 P 147bc78c9b644d87a66405abc4c0d001 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:58.909914  2584 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 147bc78c9b644d87a66405abc4c0d001 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:58.910243  2584 raft_consensus.cc:697] T 00000000000000000000000000000000 P 147bc78c9b644d87a66405abc4c0d001 [term 1 LEADER]: Becoming Leader. State: Replica: 147bc78c9b644d87a66405abc4c0d001, State: Running, Role: LEADER
I20260812 06:18:58.910691  2584 consensus_queue.cc:237] T 00000000000000000000000000000000 P 147bc78c9b644d87a66405abc4c0d001 [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: "147bc78c9b644d87a66405abc4c0d001" member_type: VOTER }
I20260812 06:18:58.910880  2581 sys_catalog.cc:565] T 00000000000000000000000000000000 P 147bc78c9b644d87a66405abc4c0d001 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:58.912838  2586 sys_catalog.cc:455] T 00000000000000000000000000000000 P 147bc78c9b644d87a66405abc4c0d001 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 147bc78c9b644d87a66405abc4c0d001. Latest consensus state: current_term: 1 leader_uuid: "147bc78c9b644d87a66405abc4c0d001" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "147bc78c9b644d87a66405abc4c0d001" member_type: VOTER } }
I20260812 06:18:58.912955  2585 sys_catalog.cc:455] T 00000000000000000000000000000000 P 147bc78c9b644d87a66405abc4c0d001 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "147bc78c9b644d87a66405abc4c0d001" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "147bc78c9b644d87a66405abc4c0d001" member_type: VOTER } }
I20260812 06:18:58.913074  2585 sys_catalog.cc:458] T 00000000000000000000000000000000 P 147bc78c9b644d87a66405abc4c0d001 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:58.912973  2586 sys_catalog.cc:458] T 00000000000000000000000000000000 P 147bc78c9b644d87a66405abc4c0d001 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:58.913565  2595 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:58.916504  2595 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:58.916823  2475 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:58.921617  2595 catalog_manager.cc:1383] Generated new cluster ID: 9fc4346f1d244d2bb620ed129f62669b
I20260812 06:18:58.921694  2595 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:58.931006  2595 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:58.932200  2595 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:58.950495  2595 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 147bc78c9b644d87a66405abc4c0d001: Generated new TSK 0
I20260812 06:18:58.951305  2595 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:58.982146  2475 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:58.985575  2610 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:58.985579  2614 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:58.986034  2611 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:58.986162  2475 server_base.cc:1061] running on GCE node
I20260812 06:18:58.986455  2475 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:58.986552  2475 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:58.986578  2475 hybrid_clock.cc:648] HybridClock initialized: now 1786515538986578 us; error 0 us; skew 500 ppm
I20260812 06:18:58.987624  2475 webserver.cc:533] Webserver started at http://127.2.106.193:41699/ using document root <none> and password file <none>
I20260812 06:18:58.987804  2475 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:58.987867  2475 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:58.987939  2475 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:58.991566  2475 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root/instance:
uuid: "5ee6489ba0fb47f59b9b11dfb90cf055"
format_stamp: "Formatted at 2026-08-12 06:18:58 on dist-test-slave-7kzw"
I20260812 06:18:58.993662  2475 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:58.995014  2622 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:58.995385  2475 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:58.995462  2475 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root
uuid: "5ee6489ba0fb47f59b9b11dfb90cf055"
format_stamp: "Formatted at 2026-08-12 06:18:58 on dist-test-slave-7kzw"
I20260812 06:18:58.995565  2475 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:59.006891  2475 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:59.007436  2475 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:59.008019  2475 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:59.008977  2475 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:59.009035  2475 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:59.009116  2475 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:59.009167  2475 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:59.016856  2475 rpc_server.cc:307] RPC server started. Bound to: 127.2.106.193:41621
I20260812 06:18:59.016894  2711 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.2.106.193:41621 every 8 connection(s)
I20260812 06:18:59.028002  2713 heartbeater.cc:344] Connected to a master server at 127.2.106.254:45823
I20260812 06:18:59.028323  2713 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:59.028878  2713 heartbeater.cc:507] Master 127.2.106.254:45823 requested a full tablet report, sending...
I20260812 06:18:59.030778  2519 ts_manager.cc:194] Registered new tserver with Master: 5ee6489ba0fb47f59b9b11dfb90cf055 (127.2.106.193:41621)
I20260812 06:18:59.031575  2475 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013972708s
I20260812 06:18:59.032367  2519 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:35788
I20260812 06:18:59.041883  2519 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:35802:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:59.057952  2653 tablet_service.cc:1511] Processing CreateTablet for tablet cdf0fcd045f54b0b89d39a8c254fc5ef (DEFAULT_TABLE table=heavy-update-compaction-test [id=f40b782a492843de8e4784120154f6ad]), partition=
I20260812 06:18:59.058432  2653 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet cdf0fcd045f54b0b89d39a8c254fc5ef. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:59.060985  2728 tablet_bootstrap.cc:492] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: Bootstrap starting.
I20260812 06:18:59.062121  2728 tablet_bootstrap.cc:654] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:59.063592  2728 tablet_bootstrap.cc:492] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: No bootstrap required, opened a new log
I20260812 06:18:59.063709  2728 ts_tablet_manager.cc:1403] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:59.064194  2728 raft_consensus.cc:359] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5ee6489ba0fb47f59b9b11dfb90cf055" member_type: VOTER last_known_addr { host: "127.2.106.193" port: 41621 } }
I20260812 06:18:59.064338  2728 raft_consensus.cc:385] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:59.064378  2728 raft_consensus.cc:740] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5ee6489ba0fb47f59b9b11dfb90cf055, State: Initialized, Role: FOLLOWER
I20260812 06:18:59.064517  2728 consensus_queue.cc:260] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055 [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: "5ee6489ba0fb47f59b9b11dfb90cf055" member_type: VOTER last_known_addr { host: "127.2.106.193" port: 41621 } }
I20260812 06:18:59.064621  2728 raft_consensus.cc:399] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:59.064658  2728 raft_consensus.cc:493] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:59.064702  2728 raft_consensus.cc:3060] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:59.065642  2728 raft_consensus.cc:515] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5ee6489ba0fb47f59b9b11dfb90cf055" member_type: VOTER last_known_addr { host: "127.2.106.193" port: 41621 } }
I20260812 06:18:59.065798  2728 leader_election.cc:304] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055 [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: 5ee6489ba0fb47f59b9b11dfb90cf055; no voters: 
I20260812 06:18:59.066008  2728 leader_election.cc:290] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:59.066208  2731 raft_consensus.cc:2804] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:59.066344  2728 ts_tablet_manager.cc:1434] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:59.066504  2731 raft_consensus.cc:697] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055 [term 1 LEADER]: Becoming Leader. State: Replica: 5ee6489ba0fb47f59b9b11dfb90cf055, State: Running, Role: LEADER
I20260812 06:18:59.066784  2713 heartbeater.cc:499] Master 127.2.106.254:45823 was elected leader, sending a full tablet report...
I20260812 06:18:59.066721  2731 consensus_queue.cc:237] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055 [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: "5ee6489ba0fb47f59b9b11dfb90cf055" member_type: VOTER last_known_addr { host: "127.2.106.193" port: 41621 } }
I20260812 06:18:59.070000  2519 catalog_manager.cc:5719] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055 reported cstate change: term changed from 0 to 1, leader changed from <none> to 5ee6489ba0fb47f59b9b11dfb90cf055 (127.2.106.193). New cstate: current_term: 1 leader_uuid: "5ee6489ba0fb47f59b9b11dfb90cf055" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5ee6489ba0fb47f59b9b11dfb90cf055" member_type: VOTER last_known_addr { host: "127.2.106.193" port: 41621 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:59.149806  2475 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.070s	user 0.019s	sys 0.015s
I20260812 06:18:59.268383  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushMRSOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=15.086190
I20260812 06:18:59.424908  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushMRSOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.156s	user 0.093s	sys 0.059s Metrics: {"bytes_written":12307491,"cfile_init":1,"compiler_manager_pool.queue_time_us":292,"delete_count":0,"dirs.queue_time_us":420,"dirs.run_cpu_time_us":258,"dirs.run_wall_time_us":850,"drs_written":1,"lbm_read_time_us":93,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41005,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"thread_start_us":165,"threads_started":1,"update_count":1500}
I20260812 06:18:59.426440  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling LogGCOp(cdf0fcd045f54b0b89d39a8c254fc5ef): free 8725963 bytes of WAL
I20260812 06:18:59.426851  2628 log_reader.cc:385] T cdf0fcd045f54b0b89d39a8c254fc5ef: removed 1 log segments from log reader
I20260812 06:18:59.426945  2628 log.cc:1079] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/cdf0fcd045f54b0b89d39a8c254fc5ef/wal-000000001 (ops 1-6)
I20260812 06:18:59.429809  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: LogGCOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:59.430346  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling UndoDeltaBlockGCOp(cdf0fcd045f54b0b89d39a8c254fc5ef): 12308960 bytes on disk
I20260812 06:18:59.431236  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: UndoDeltaBlockGCOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":85,"lbm_reads_lt_1ms":4}
I20260812 06:18:59.431813  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=2.188937
I20260812 06:18:59.463762  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.032s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6815,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.464293  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=2.188937
I20260812 06:18:59.478451  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.014s	user 0.001s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5644,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.478963  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=1.000000
I20260812 06:18:59.646162  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.167s	user 0.118s	sys 0.048s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733844,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":938,"lbm_read_time_us":10506,"lbm_reads_lt_1ms":569,"lbm_write_time_us":31846,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3328,"thread_start_us":335,"threads_started":5,"update_count":2500}
I20260812 06:18:59.646667  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=10.126437
I20260812 06:18:59.696741  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.050s	user 0.030s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17243,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:59.697316  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=2.188937
I20260812 06:18:59.708151  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4216,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.708735  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=1.000000
I20260812 06:18:59.832486  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.123s	user 0.104s	sys 0.018s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1044,"lbm_read_time_us":8843,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24486,"lbm_writes_lt_1ms":443,"mutex_wait_us":315,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2000}
I20260812 06:18:59.833107  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=10.126437
I20260812 06:18:59.873718  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.040s	user 0.026s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18015,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:59.874238  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=1.000000
I20260812 06:18:59.978262  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.104s	user 0.090s	sys 0.011s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528782,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":258,"lbm_read_time_us":5956,"lbm_reads_lt_1ms":363,"lbm_write_time_us":19606,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":20864,"update_count":1500}
I20260812 06:18:59.978878  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=10.126437
I20260812 06:19:00.020570  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.041s	user 0.028s	sys 0.010s Metrics: {"bytes_written":12307494,"delete_count":0,"lbm_write_time_us":17414,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:00.021344  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=2.188937
I20260812 06:19:00.041531  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.020s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6485,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.042182  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=1.000000
I20260812 06:19:00.181180  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.139s	user 0.111s	sys 0.026s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631316,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":266,"lbm_read_time_us":9481,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27667,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:00.181860  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=10.126437
I20260812 06:19:00.229049  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.047s	user 0.022s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20840,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:19:00.229568  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=2.188937
I20260812 06:19:00.240955  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4130,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.241626  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=1.000000
I20260812 06:19:00.366815  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.125s	user 0.096s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":669,"lbm_read_time_us":9194,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24417,"lbm_writes_lt_1ms":443,"mutex_wait_us":63,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2000}
I20260812 06:19:00.367431  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=10.126437
I20260812 06:19:00.405385  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.038s	user 0.018s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16446,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:00.405893  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=2.188937
I20260812 06:19:00.417599  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4510,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.418128  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=1.000000
I20260812 06:19:00.545210  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.127s	user 0.094s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":382,"lbm_read_time_us":9399,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23075,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:19:00.545823  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=10.126437
I20260812 06:19:00.592288  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.046s	user 0.013s	sys 0.031s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17367,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:00.592859  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=2.188937
I20260812 06:19:00.603451  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4054,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.604071  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushMRSOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=1.000000
I20260812 06:19:00.640398  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushMRSOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.036s	user 0.022s	sys 0.007s Metrics: {"bytes_written":1152509,"cfile_init":1,"dirs.queue_time_us":136,"dirs.run_cpu_time_us":268,"dirs.run_wall_time_us":1252,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2053,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:00.641197  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling LogGCOp(cdf0fcd045f54b0b89d39a8c254fc5ef): free 120100260 bytes of WAL
I20260812 06:19:00.641427  2628 log_reader.cc:385] T cdf0fcd045f54b0b89d39a8c254fc5ef: removed 12 log segments from log reader
I20260812 06:19:00.641469  2628 log.cc:1079] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/cdf0fcd045f54b0b89d39a8c254fc5ef/wal-000000002 (ops 7-11)
I20260812 06:19:00.641498  2628 log.cc:1079] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/cdf0fcd045f54b0b89d39a8c254fc5ef/wal-000000003 (ops 12-16)
I20260812 06:19:00.641559  2628 log.cc:1079] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/cdf0fcd045f54b0b89d39a8c254fc5ef/wal-000000004 (ops 17-21)
I20260812 06:19:00.641606  2628 log.cc:1079] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/cdf0fcd045f54b0b89d39a8c254fc5ef/wal-000000005 (ops 22-26)
I20260812 06:19:00.641649  2628 log.cc:1079] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/cdf0fcd045f54b0b89d39a8c254fc5ef/wal-000000006 (ops 27-30)
I20260812 06:19:00.641690  2628 log.cc:1079] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/cdf0fcd045f54b0b89d39a8c254fc5ef/wal-000000007 (ops 31-35)
I20260812 06:19:00.641728  2628 log.cc:1079] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/cdf0fcd045f54b0b89d39a8c254fc5ef/wal-000000008 (ops 36-40)
I20260812 06:19:00.641758  2628 log.cc:1079] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/cdf0fcd045f54b0b89d39a8c254fc5ef/wal-000000009 (ops 41-44)
I20260812 06:19:00.641803  2628 log.cc:1079] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/cdf0fcd045f54b0b89d39a8c254fc5ef/wal-000000010 (ops 45-49)
I20260812 06:19:00.641847  2628 log.cc:1079] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/cdf0fcd045f54b0b89d39a8c254fc5ef/wal-000000011 (ops 50-54)
I20260812 06:19:00.641888  2628 log.cc:1079] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/cdf0fcd045f54b0b89d39a8c254fc5ef/wal-000000012 (ops 55-58)
I20260812 06:19:00.641927  2628 log.cc:1079] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/cdf0fcd045f54b0b89d39a8c254fc5ef/wal-000000013 (ops 59-63)
I20260812 06:19:00.669016  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: LogGCOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:19:00.669492  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling UndoDeltaBlockGCOp(cdf0fcd045f54b0b89d39a8c254fc5ef): 447 bytes on disk
I20260812 06:19:00.670053  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: UndoDeltaBlockGCOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:19:00.670650  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=2.188937
I20260812 06:19:00.690881  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.020s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6094,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.691311  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=2.188937
I20260812 06:19:00.701364  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3946,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.701771  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=1.000000
I20260812 06:19:00.908665  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.207s	user 0.118s	sys 0.075s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836373,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1167,"lbm_read_time_us":13648,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33444,"lbm_writes_lt_1ms":643,"mutex_wait_us":29,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":22144,"thread_start_us":82,"threads_started":1,"update_count":3000}
I20260812 06:19:00.909341  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=14.095187
I20260812 06:19:00.960546  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.051s	user 0.033s	sys 0.015s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":22092,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:00.961158  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=1.000000
I20260812 06:19:01.127954  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.167s	user 0.115s	sys 0.040s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631196,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":241,"lbm_read_time_us":10636,"lbm_reads_lt_1ms":463,"lbm_write_time_us":26106,"lbm_writes_lt_1ms":443,"mutex_wait_us":86,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:01.128674  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=14.095187
I20260812 06:19:01.180958  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.052s	user 0.035s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22605,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:01.181582  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=2.188937
I20260812 06:19:01.193143  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4032,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.193676  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=1.000000
I20260812 06:19:01.394412  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.201s	user 0.146s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1027,"lbm_read_time_us":11306,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32283,"lbm_writes_lt_1ms":543,"mutex_wait_us":88,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12160,"update_count":2500}
I20260812 06:19:01.395177  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=14.095187
I20260812 06:19:01.446215  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.051s	user 0.029s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21513,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:01.446771  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=2.188937
I20260812 06:19:01.460572  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.014s	user 0.003s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4849,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.461061  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=1.000000
I20260812 06:19:01.623195  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.162s	user 0.139s	sys 0.023s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":841,"lbm_read_time_us":12234,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32213,"lbm_writes_lt_1ms":543,"mutex_wait_us":82,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:19:01.623790  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=10.126437
I20260812 06:19:01.655185  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.031s	user 0.026s	sys 0.004s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":13754,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:01.655933  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=2.188937
I20260812 06:19:01.672183  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.016s	user 0.000s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5787,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.672643  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=1.000000
I20260812 06:19:01.808463  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.136s	user 0.091s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":317,"lbm_read_time_us":10177,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25826,"lbm_writes_lt_1ms":443,"mutex_wait_us":82,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:19:01.809337  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=10.126437
I20260812 06:19:01.854692  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.045s	user 0.019s	sys 0.019s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17106,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:01.855207  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=2.188937
I20260812 06:19:01.867558  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4538,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.868239  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=1.000000
I20260812 06:19:01.998611  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.130s	user 0.125s	sys 0.004s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":524,"lbm_read_time_us":10718,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22659,"lbm_writes_lt_1ms":443,"mutex_wait_us":45,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2000}
I20260812 06:19:01.999411  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=10.126437
I20260812 06:19:02.050225  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.050s	user 0.023s	sys 0.023s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18024,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:02.050866  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=2.188937
I20260812 06:19:02.061599  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4102,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.062088  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushMRSOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=1.000000
I20260812 06:19:02.104827  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushMRSOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.043s	user 0.028s	sys 0.003s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":220,"dirs.run_wall_time_us":1343,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1430,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:02.105612  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling LogGCOp(cdf0fcd045f54b0b89d39a8c254fc5ef): free 115943233 bytes of WAL
I20260812 06:19:02.105877  2628 log_reader.cc:385] T cdf0fcd045f54b0b89d39a8c254fc5ef: removed 11 log segments from log reader
I20260812 06:19:02.105968  2628 log.cc:1079] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/cdf0fcd045f54b0b89d39a8c254fc5ef/wal-000000014 (ops 64-68)
I20260812 06:19:02.106073  2628 log.cc:1079] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/cdf0fcd045f54b0b89d39a8c254fc5ef/wal-000000015 (ops 69-73)
I20260812 06:19:02.106153  2628 log.cc:1079] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/cdf0fcd045f54b0b89d39a8c254fc5ef/wal-000000016 (ops 74-78)
I20260812 06:19:02.106211  2628 log.cc:1079] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/cdf0fcd045f54b0b89d39a8c254fc5ef/wal-000000017 (ops 79-83)
I20260812 06:19:02.106271  2628 log.cc:1079] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/cdf0fcd045f54b0b89d39a8c254fc5ef/wal-000000018 (ops 84-88)
I20260812 06:19:02.106317  2628 log.cc:1079] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/cdf0fcd045f54b0b89d39a8c254fc5ef/wal-000000019 (ops 89-93)
I20260812 06:19:02.106379  2628 log.cc:1079] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/cdf0fcd045f54b0b89d39a8c254fc5ef/wal-000000020 (ops 94-98)
I20260812 06:19:02.106417  2628 log.cc:1079] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/cdf0fcd045f54b0b89d39a8c254fc5ef/wal-000000021 (ops 99-103)
I20260812 06:19:02.106452  2628 log.cc:1079] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/cdf0fcd045f54b0b89d39a8c254fc5ef/wal-000000022 (ops 104-108)
I20260812 06:19:02.106534  2628 log.cc:1079] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/cdf0fcd045f54b0b89d39a8c254fc5ef/wal-000000023 (ops 109-113)
I20260812 06:19:02.106603  2628 log.cc:1079] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/cdf0fcd045f54b0b89d39a8c254fc5ef/wal-000000024 (ops 114-118)
I20260812 06:19:02.134039  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: LogGCOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:19:02.134794  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling UndoDeltaBlockGCOp(cdf0fcd045f54b0b89d39a8c254fc5ef): 448 bytes on disk
I20260812 06:19:02.135387  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: UndoDeltaBlockGCOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:19:02.135972  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=3.181125
I20260812 06:19:02.156349  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.020s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7085,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:02.156932  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=2.188937
I20260812 06:19:02.166613  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.009s	user 0.004s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3564,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:02.167167  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=1.000000
I20260812 06:19:02.383903  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.216s	user 0.134s	sys 0.073s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836361,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1612,"lbm_read_time_us":13907,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35828,"lbm_writes_lt_1ms":643,"mutex_wait_us":545,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2176,"thread_start_us":102,"threads_started":1,"update_count":3000}
I20260812 06:19:02.384562  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=14.095187
I20260812 06:19:02.445012  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.060s	user 0.038s	sys 0.016s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":25634,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:02.445667  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=1.000000
I20260812 06:19:02.608665  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.163s	user 0.112s	sys 0.040s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631196,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":645,"lbm_read_time_us":10168,"lbm_reads_lt_1ms":463,"lbm_write_time_us":25069,"lbm_writes_lt_1ms":443,"mutex_wait_us":67,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":2000}
I20260812 06:19:02.609485  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=14.095187
I20260812 06:19:02.666294  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.057s	user 0.027s	sys 0.026s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":26687,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:02.666884  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=2.188937
I20260812 06:19:02.679412  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.012s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4511,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.679970  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=1.000000
I20260812 06:19:02.870579  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.190s	user 0.131s	sys 0.054s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":377,"lbm_read_time_us":12927,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29954,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:02.871316  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=14.095187
I20260812 06:19:02.917548  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.046s	user 0.014s	sys 0.028s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20563,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:02.918028  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=2.188937
I20260812 06:19:02.930332  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4699,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.930989  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=1.000000
I20260812 06:19:03.081482  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.150s	user 0.110s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733726,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":107,"lbm_read_time_us":9740,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32756,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":35200,"update_count":2500}
I20260812 06:19:03.082182  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=11.118625
I20260812 06:19:03.121937  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.040s	user 0.019s	sys 0.017s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16998,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:03.122638  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=2.188937
I20260812 06:19:03.137466  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.015s	user 0.003s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4741,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:03.137995  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=1.000000
I20260812 06:19:03.267570  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.129s	user 0.097s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":68,"lbm_read_time_us":9030,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24382,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":2000}
I20260812 06:19:03.268380  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=10.126437
I20260812 06:19:03.313426  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.045s	user 0.020s	sys 0.015s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16450,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:03.314093  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=2.188937
I20260812 06:19:03.329895  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5835,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.330677  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=1.000000
I20260812 06:19:03.479182  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.148s	user 0.097s	sys 0.050s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":970,"lbm_read_time_us":11136,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28049,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2000}
I20260812 06:19:03.479897  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=10.126437
I20260812 06:19:03.531253  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.051s	user 0.032s	sys 0.019s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16702,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:03.531865  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=2.188937
I20260812 06:19:03.544133  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.012s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4635,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.544646  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushMRSOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=1.000000
I20260812 06:19:03.570823  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushMRSOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.026s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1152511,"cfile_init":1,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":208,"dirs.run_wall_time_us":1363,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1395,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:03.571566  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling LogGCOp(cdf0fcd045f54b0b89d39a8c254fc5ef): free 121006648 bytes of WAL
I20260812 06:19:03.571868  2628 log_reader.cc:385] T cdf0fcd045f54b0b89d39a8c254fc5ef: removed 12 log segments from log reader
I20260812 06:19:03.571933  2628 log.cc:1079] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/cdf0fcd045f54b0b89d39a8c254fc5ef/wal-000000025 (ops 119-123)
I20260812 06:19:03.571972  2628 log.cc:1079] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/cdf0fcd045f54b0b89d39a8c254fc5ef/wal-000000026 (ops 124-128)
I20260812 06:19:03.571995  2628 log.cc:1079] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/cdf0fcd045f54b0b89d39a8c254fc5ef/wal-000000027 (ops 129-133)
I20260812 06:19:03.572029  2628 log.cc:1079] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/cdf0fcd045f54b0b89d39a8c254fc5ef/wal-000000028 (ops 134-138)
I20260812 06:19:03.572063  2628 log.cc:1079] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/cdf0fcd045f54b0b89d39a8c254fc5ef/wal-000000029 (ops 139-142)
I20260812 06:19:03.572093  2628 log.cc:1079] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/cdf0fcd045f54b0b89d39a8c254fc5ef/wal-000000030 (ops 143-147)
I20260812 06:19:03.572124  2628 log.cc:1079] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/cdf0fcd045f54b0b89d39a8c254fc5ef/wal-000000031 (ops 148-152)
I20260812 06:19:03.572151  2628 log.cc:1079] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/cdf0fcd045f54b0b89d39a8c254fc5ef/wal-000000032 (ops 153-157)
I20260812 06:19:03.572178  2628 log.cc:1079] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/cdf0fcd045f54b0b89d39a8c254fc5ef/wal-000000033 (ops 158-162)
I20260812 06:19:03.572213  2628 log.cc:1079] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/cdf0fcd045f54b0b89d39a8c254fc5ef/wal-000000034 (ops 163-167)
I20260812 06:19:03.572247  2628 log.cc:1079] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/cdf0fcd045f54b0b89d39a8c254fc5ef/wal-000000035 (ops 168-172)
I20260812 06:19:03.572278  2628 log.cc:1079] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/cdf0fcd045f54b0b89d39a8c254fc5ef/wal-000000036 (ops 173-177)
I20260812 06:19:03.602173  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: LogGCOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.030s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:03.602705  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=2.188937
I20260812 06:19:03.628209  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.025s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4437,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.628692  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling UndoDeltaBlockGCOp(cdf0fcd045f54b0b89d39a8c254fc5ef): 447 bytes on disk
I20260812 06:19:03.629133  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: UndoDeltaBlockGCOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:19:03.629660  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=2.188937
I20260812 06:19:03.640384  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4107,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.641017  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=1.000000
I20260812 06:19:03.845299  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.204s	user 0.152s	sys 0.048s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836373,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":981,"lbm_read_time_us":13527,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33373,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4864,"thread_start_us":82,"threads_started":1,"update_count":3000}
I20260812 06:19:03.846155  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=14.095187
I20260812 06:19:03.894428  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.048s	user 0.040s	sys 0.004s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20715,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:03.895007  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=1.000000
I20260812 06:19:04.035099  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.140s	user 0.099s	sys 0.040s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631191,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":650,"lbm_read_time_us":8966,"lbm_reads_lt_1ms":467,"lbm_write_time_us":24669,"lbm_writes_lt_1ms":443,"mutex_wait_us":358,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14464,"update_count":2000}
I20260812 06:19:04.035851  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=10.126437
I20260812 06:19:04.071092  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.035s	user 0.026s	sys 0.007s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":15078,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:04.071831  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=2.188937
I20260812 06:19:04.091302  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.019s	user 0.014s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7375,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.091877  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=1.000000
I20260812 06:19:04.215565  2475 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.066s	user 1.874s	sys 0.141s
I20260812 06:19:04.224299  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.132s	user 0.109s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631315,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"lbm_read_time_us":9531,"lbm_reads_lt_1ms":468,"lbm_write_time_us":24290,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2000}
I20260812 06:19:04.224960  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=10.126437
I20260812 06:19:04.249769  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: FlushDeltaMemStoresOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.025s	user 0.016s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":11960,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:04.250456  2714 maintenance_manager.cc:419] P 5ee6489ba0fb47f59b9b11dfb90cf055: Scheduling MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef): perf score=1.000000
I20260812 06:19:04.270879  2475 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.055s	user 0.005s	sys 0.000s
I20260812 06:19:04.271654  2475 tablet_server.cc:179] TabletServer@127.2.106.193:0 shutting down...
I20260812 06:19:04.347604  2628 maintenance_manager.cc:643] P 5ee6489ba0fb47f59b9b11dfb90cf055: MajorDeltaCompactionOp(cdf0fcd045f54b0b89d39a8c254fc5ef) complete. Timing: real 0.097s	user 0.074s	sys 0.022s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528782,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":865,"lbm_read_time_us":7807,"lbm_reads_lt_1ms":367,"lbm_write_time_us":20096,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":342,"mutex_wait_us":74,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1500}
I20260812 06:19:04.348327  2475 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:04.348857  2475 tablet_replica.cc:333] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055: stopping tablet replica
I20260812 06:19:04.349113  2475 raft_consensus.cc:2243] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:04.349367  2475 raft_consensus.cc:2272] T cdf0fcd045f54b0b89d39a8c254fc5ef P 5ee6489ba0fb47f59b9b11dfb90cf055 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:04.364938  2475 tablet_server.cc:196] TabletServer@127.2.106.193:0 shutdown complete.
I20260812 06:19:04.380329  2475 master.cc:562] Master@127.2.106.254:45823 shutting down...
I20260812 06:19:04.384521  2475 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 147bc78c9b644d87a66405abc4c0d001 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:04.384722  2475 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 147bc78c9b644d87a66405abc4c0d001 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:04.384795  2475 tablet_replica.cc:333] T 00000000000000000000000000000000 P 147bc78c9b644d87a66405abc4c0d001: stopping tablet replica
I20260812 06:19:04.397394  2475 master.cc:584] Master@127.2.106.254:45823 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5669 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:04.518885  2475 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.2.106.254:41259
I20260812 06:19:04.519366  2475 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:04.521924  2756 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:04.522018  2759 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:04.522053  2475 server_base.cc:1061] running on GCE node
W20260812 06:19:04.522010  2762 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:04.522568  2475 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:04.522619  2475 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:04.522637  2475 hybrid_clock.cc:648] HybridClock initialized: now 1786515544522638 us; error 0 us; skew 500 ppm
I20260812 06:19:04.523684  2475 webserver.cc:533] Webserver started at http://127.2.106.254:45369/ using document root <none> and password file <none>
I20260812 06:19:04.523904  2475 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:04.523994  2475 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:04.524091  2475 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:04.524565  2475 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/master-0-root/instance:
uuid: "57ffc59dc4f04625a35a092bea105331"
format_stamp: "Formatted at 2026-08-12 06:19:04 on dist-test-slave-7kzw"
I20260812 06:19:04.526433  2475 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:04.527652  2769 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:04.527969  2475 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:04.528050  2475 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/master-0-root
uuid: "57ffc59dc4f04625a35a092bea105331"
format_stamp: "Formatted at 2026-08-12 06:19:04 on dist-test-slave-7kzw"
I20260812 06:19:04.528111  2475 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-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:04.543128  2475 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:04.543701  2475 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:04.551041  2475 rpc_server.cc:307] RPC server started. Bound to: 127.2.106.254:41259
I20260812 06:19:04.558728  2852 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.2.106.254:41259 every 8 connection(s)
I20260812 06:19:04.559316  2853 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:04.561426  2853 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 57ffc59dc4f04625a35a092bea105331: Bootstrap starting.
I20260812 06:19:04.562340  2853 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 57ffc59dc4f04625a35a092bea105331: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:04.563763  2853 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 57ffc59dc4f04625a35a092bea105331: No bootstrap required, opened a new log
I20260812 06:19:04.564347  2853 raft_consensus.cc:359] T 00000000000000000000000000000000 P 57ffc59dc4f04625a35a092bea105331 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "57ffc59dc4f04625a35a092bea105331" member_type: VOTER }
I20260812 06:19:04.564468  2853 raft_consensus.cc:385] T 00000000000000000000000000000000 P 57ffc59dc4f04625a35a092bea105331 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:04.564520  2853 raft_consensus.cc:740] T 00000000000000000000000000000000 P 57ffc59dc4f04625a35a092bea105331 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 57ffc59dc4f04625a35a092bea105331, State: Initialized, Role: FOLLOWER
I20260812 06:19:04.564715  2853 consensus_queue.cc:260] T 00000000000000000000000000000000 P 57ffc59dc4f04625a35a092bea105331 [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: "57ffc59dc4f04625a35a092bea105331" member_type: VOTER }
I20260812 06:19:04.564832  2853 raft_consensus.cc:399] T 00000000000000000000000000000000 P 57ffc59dc4f04625a35a092bea105331 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:04.564893  2853 raft_consensus.cc:493] T 00000000000000000000000000000000 P 57ffc59dc4f04625a35a092bea105331 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:04.564966  2853 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 57ffc59dc4f04625a35a092bea105331 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:04.565795  2853 raft_consensus.cc:515] T 00000000000000000000000000000000 P 57ffc59dc4f04625a35a092bea105331 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "57ffc59dc4f04625a35a092bea105331" member_type: VOTER }
I20260812 06:19:04.565922  2853 leader_election.cc:304] T 00000000000000000000000000000000 P 57ffc59dc4f04625a35a092bea105331 [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: 57ffc59dc4f04625a35a092bea105331; no voters: 
I20260812 06:19:04.566088  2853 leader_election.cc:290] T 00000000000000000000000000000000 P 57ffc59dc4f04625a35a092bea105331 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:04.566267  2856 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 57ffc59dc4f04625a35a092bea105331 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:04.566494  2856 raft_consensus.cc:697] T 00000000000000000000000000000000 P 57ffc59dc4f04625a35a092bea105331 [term 1 LEADER]: Becoming Leader. State: Replica: 57ffc59dc4f04625a35a092bea105331, State: Running, Role: LEADER
I20260812 06:19:04.566637  2856 consensus_queue.cc:237] T 00000000000000000000000000000000 P 57ffc59dc4f04625a35a092bea105331 [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: "57ffc59dc4f04625a35a092bea105331" member_type: VOTER }
I20260812 06:19:04.566761  2853 sys_catalog.cc:565] T 00000000000000000000000000000000 P 57ffc59dc4f04625a35a092bea105331 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:04.567116  2857 sys_catalog.cc:455] T 00000000000000000000000000000000 P 57ffc59dc4f04625a35a092bea105331 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "57ffc59dc4f04625a35a092bea105331" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "57ffc59dc4f04625a35a092bea105331" member_type: VOTER } }
I20260812 06:19:04.567219  2857 sys_catalog.cc:458] T 00000000000000000000000000000000 P 57ffc59dc4f04625a35a092bea105331 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:04.567463  2858 sys_catalog.cc:455] T 00000000000000000000000000000000 P 57ffc59dc4f04625a35a092bea105331 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 57ffc59dc4f04625a35a092bea105331. Latest consensus state: current_term: 1 leader_uuid: "57ffc59dc4f04625a35a092bea105331" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "57ffc59dc4f04625a35a092bea105331" member_type: VOTER } }
I20260812 06:19:04.567559  2858 sys_catalog.cc:458] T 00000000000000000000000000000000 P 57ffc59dc4f04625a35a092bea105331 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:04.567998  2862 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:04.568802  2862 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:04.569303  2475 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:04.571177  2862 catalog_manager.cc:1383] Generated new cluster ID: 3c6e1f7c1cd1443fbf0066401e82a808
I20260812 06:19:04.571246  2862 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:04.595368  2862 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:04.596167  2862 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:04.611837  2862 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 57ffc59dc4f04625a35a092bea105331: Generated new TSK 0
I20260812 06:19:04.612103  2862 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:04.634225  2475 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:04.636534  2885 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:04.636667  2883 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:04.636790  2882 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:04.636814  2475 server_base.cc:1061] running on GCE node
I20260812 06:19:04.637049  2475 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:04.637099  2475 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:04.637115  2475 hybrid_clock.cc:648] HybridClock initialized: now 1786515544637115 us; error 0 us; skew 500 ppm
I20260812 06:19:04.638108  2475 webserver.cc:533] Webserver started at http://127.2.106.193:44041/ using document root <none> and password file <none>
I20260812 06:19:04.638307  2475 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:04.638386  2475 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:04.638495  2475 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:04.638917  2475 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root/instance:
uuid: "2306b0e15d484b55b30bddb0c99d621d"
format_stamp: "Formatted at 2026-08-12 06:19:04 on dist-test-slave-7kzw"
I20260812 06:19:04.640547  2475 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:04.641726  2893 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:04.642115  2475 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:04.642191  2475 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root
uuid: "2306b0e15d484b55b30bddb0c99d621d"
format_stamp: "Formatted at 2026-08-12 06:19:04 on dist-test-slave-7kzw"
I20260812 06:19:04.642299  2475 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-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:04.652778  2475 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:04.653190  2475 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:04.653524  2475 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:04.654031  2475 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:04.654071  2475 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:04.654106  2475 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:04.654121  2475 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:04.658658  2475 rpc_server.cc:307] RPC server started. Bound to: 127.2.106.193:37151
I20260812 06:19:04.659109  2993 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.2.106.193:37151 every 8 connection(s)
I20260812 06:19:04.664042  2995 heartbeater.cc:344] Connected to a master server at 127.2.106.254:41259
I20260812 06:19:04.664152  2995 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:04.664350  2995 heartbeater.cc:507] Master 127.2.106.254:41259 requested a full tablet report, sending...
I20260812 06:19:04.665081  2796 ts_manager.cc:194] Registered new tserver with Master: 2306b0e15d484b55b30bddb0c99d621d (127.2.106.193:37151)
I20260812 06:19:04.665751  2796 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:47998
I20260812 06:19:04.666056  2475 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.006729717s
I20260812 06:19:04.673918  2796 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:48002:
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:04.683682  2937 tablet_service.cc:1511] Processing CreateTablet for tablet 5c0253e2be5644b8a2f9230b6b76dff1 (DEFAULT_TABLE table=heavy-update-compaction-test [id=ff8cdeafcb5945a8aad69eedbd5c564f]), partition=
I20260812 06:19:04.683995  2937 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 5c0253e2be5644b8a2f9230b6b76dff1. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:04.685928  3009 tablet_bootstrap.cc:492] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Bootstrap starting.
I20260812 06:19:04.686951  3009 tablet_bootstrap.cc:654] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:04.688155  3009 tablet_bootstrap.cc:492] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: No bootstrap required, opened a new log
I20260812 06:19:04.688275  3009 ts_tablet_manager.cc:1403] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:04.688828  3009 raft_consensus.cc:359] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2306b0e15d484b55b30bddb0c99d621d" member_type: VOTER last_known_addr { host: "127.2.106.193" port: 37151 } }
I20260812 06:19:04.688946  3009 raft_consensus.cc:385] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:04.688999  3009 raft_consensus.cc:740] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 2306b0e15d484b55b30bddb0c99d621d, State: Initialized, Role: FOLLOWER
I20260812 06:19:04.689194  3009 consensus_queue.cc:260] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d [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: "2306b0e15d484b55b30bddb0c99d621d" member_type: VOTER last_known_addr { host: "127.2.106.193" port: 37151 } }
I20260812 06:19:04.689273  3009 raft_consensus.cc:399] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:04.689334  3009 raft_consensus.cc:493] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:04.689391  3009 raft_consensus.cc:3060] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:04.690171  3009 raft_consensus.cc:515] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2306b0e15d484b55b30bddb0c99d621d" member_type: VOTER last_known_addr { host: "127.2.106.193" port: 37151 } }
I20260812 06:19:04.690330  3009 leader_election.cc:304] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d [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: 2306b0e15d484b55b30bddb0c99d621d; no voters: 
I20260812 06:19:04.690587  3009 leader_election.cc:290] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:04.690681  3011 raft_consensus.cc:2804] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:04.690940  3011 raft_consensus.cc:697] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d [term 1 LEADER]: Becoming Leader. State: Replica: 2306b0e15d484b55b30bddb0c99d621d, State: Running, Role: LEADER
I20260812 06:19:04.690995  3009 ts_tablet_manager.cc:1434] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Time spent starting tablet: real 0.003s	user 0.001s	sys 0.002s
I20260812 06:19:04.691038  2995 heartbeater.cc:499] Master 127.2.106.254:41259 was elected leader, sending a full tablet report...
I20260812 06:19:04.691228  3011 consensus_queue.cc:237] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d [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: "2306b0e15d484b55b30bddb0c99d621d" member_type: VOTER last_known_addr { host: "127.2.106.193" port: 37151 } }
I20260812 06:19:04.692677  2796 catalog_manager.cc:5719] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d reported cstate change: term changed from 0 to 1, leader changed from <none> to 2306b0e15d484b55b30bddb0c99d621d (127.2.106.193). New cstate: current_term: 1 leader_uuid: "2306b0e15d484b55b30bddb0c99d621d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2306b0e15d484b55b30bddb0c99d621d" member_type: VOTER last_known_addr { host: "127.2.106.193" port: 37151 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:04.753584  2475 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.015s	sys 0.008s
I20260812 06:19:04.910082  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushMRSOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=19.054940
I20260812 06:19:05.073594  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushMRSOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.163s	user 0.117s	sys 0.043s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":84,"dirs.run_cpu_time_us":182,"dirs.run_wall_time_us":761,"drs_written":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41046,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:19:05.074615  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling LogGCOp(5c0253e2be5644b8a2f9230b6b76dff1): free 20743880 bytes of WAL
I20260812 06:19:05.074927  2900 log_reader.cc:385] T 5c0253e2be5644b8a2f9230b6b76dff1: removed 2 log segments from log reader
I20260812 06:19:05.075001  2900 log.cc:1079] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/5c0253e2be5644b8a2f9230b6b76dff1/wal-000000001 (ops 1-6)
I20260812 06:19:05.075065  2900 log.cc:1079] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/5c0253e2be5644b8a2f9230b6b76dff1/wal-000000002 (ops 7-11)
I20260812 06:19:05.081933  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: LogGCOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.007s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:19:05.082299  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling UndoDeltaBlockGCOp(5c0253e2be5644b8a2f9230b6b76dff1): 16411395 bytes on disk
I20260812 06:19:05.082764  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: UndoDeltaBlockGCOp(5c0253e2be5644b8a2f9230b6b76dff1) 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:05.083186  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=3.181125
I20260812 06:19:05.095670  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4901,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:05.096117  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling MajorDeltaCompactionOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=1.000000
I20260812 06:19:05.261263  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: MajorDeltaCompactionOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.165s	user 0.122s	sys 0.043s Metrics: {"cfile_cache_miss":442,"cfile_cache_miss_bytes":21082518,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":763,"lbm_read_time_us":10994,"lbm_reads_lt_1ms":470,"lbm_write_time_us":25170,"lbm_writes_lt_1ms":453,"mutex_wait_us":36,"peak_mem_usage":51099678,"reinsert_count":0,"spinlock_wait_cycles":21248,"thread_start_us":448,"threads_started":5,"update_count":2050}
I20260812 06:19:05.261996  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=14.095187
I20260812 06:19:05.315049  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.053s	user 0.033s	sys 0.019s Metrics: {"bytes_written":15999661,"delete_count":0,"lbm_write_time_us":19076,"lbm_writes_lt_1ms":393,"reinsert_count":0,"update_count":1950}
I20260812 06:19:05.315634  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=2.188937
I20260812 06:19:05.332455  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.017s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6694,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.332921  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling MajorDeltaCompactionOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=1.000000
I20260812 06:19:05.523406  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: MajorDeltaCompactionOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.190s	user 0.110s	sys 0.068s Metrics: {"cfile_cache_miss":522,"cfile_cache_miss_bytes":24364448,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":860,"lbm_read_time_us":13978,"lbm_reads_lt_1ms":562,"lbm_write_time_us":27770,"lbm_writes_lt_1ms":533,"mutex_wait_us":37,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2450}
I20260812 06:19:05.524111  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=14.095187
I20260812 06:19:05.576066  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.052s	user 0.026s	sys 0.023s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22763,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:05.576591  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=2.188937
I20260812 06:19:05.591463  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5664,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.591954  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling MajorDeltaCompactionOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=1.000000
I20260812 06:19:05.774264  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: MajorDeltaCompactionOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.182s	user 0.128s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":616,"lbm_read_time_us":11826,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28490,"lbm_writes_lt_1ms":543,"mutex_wait_us":330,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":2500}
I20260812 06:19:05.774947  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=11.118625
I20260812 06:19:05.815501  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.040s	user 0.036s	sys 0.003s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":17042,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:05.816254  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=2.188937
I20260812 06:19:05.840193  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.024s	user 0.001s	sys 0.012s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5770,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:05.840682  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=2.188937
I20260812 06:19:05.852156  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4216,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.852850  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling MajorDeltaCompactionOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=1.000000
I20260812 06:19:06.010782  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: MajorDeltaCompactionOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.158s	user 0.110s	sys 0.048s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":232,"lbm_read_time_us":10182,"lbm_reads_lt_1ms":573,"lbm_write_time_us":35194,"lbm_writes_lt_1ms":543,"mutex_wait_us":45,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2500}
I20260812 06:19:06.011857  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=11.118625
I20260812 06:19:06.045130  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.033s	user 0.021s	sys 0.009s Metrics: {"bytes_written":12512614,"delete_count":0,"lbm_write_time_us":14220,"lbm_writes_lt_1ms":308,"reinsert_count":0,"update_count":1525}
I20260812 06:19:06.045778  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=2.188937
I20260812 06:19:06.060905  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3897534,"delete_count":0,"lbm_write_time_us":5207,"lbm_writes_lt_1ms":98,"reinsert_count":0,"update_count":475}
I20260812 06:19:06.061496  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling MajorDeltaCompactionOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=1.000000
I20260812 06:19:06.193188  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: MajorDeltaCompactionOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.131s	user 0.105s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":447,"lbm_read_time_us":8022,"lbm_reads_lt_1ms":468,"lbm_write_time_us":25141,"lbm_writes_lt_1ms":443,"mutex_wait_us":111,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13440,"update_count":2000}
I20260812 06:19:06.193794  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=11.118625
I20260812 06:19:06.235807  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.042s	user 0.019s	sys 0.020s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":18775,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":310,"reinsert_count":0,"update_count":1550}
I20260812 06:19:06.236707  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=2.188937
I20260812 06:19:06.266443  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.029s	user 0.011s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6027,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":450}
I20260812 06:19:06.267127  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=2.188937
I20260812 06:19:06.282234  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5723,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.282924  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushMRSOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=1.000000
I20260812 06:19:06.312427  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushMRSOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.029s	user 0.022s	sys 0.004s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":306,"dirs.run_wall_time_us":1534,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1560,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:06.313062  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling LogGCOp(5c0253e2be5644b8a2f9230b6b76dff1): free 115943184 bytes of WAL
I20260812 06:19:06.313303  2900 log_reader.cc:385] T 5c0253e2be5644b8a2f9230b6b76dff1: removed 11 log segments from log reader
I20260812 06:19:06.313349  2900 log.cc:1079] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/5c0253e2be5644b8a2f9230b6b76dff1/wal-000000003 (ops 12-16)
I20260812 06:19:06.313378  2900 log.cc:1079] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/5c0253e2be5644b8a2f9230b6b76dff1/wal-000000004 (ops 17-21)
I20260812 06:19:06.313444  2900 log.cc:1079] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/5c0253e2be5644b8a2f9230b6b76dff1/wal-000000005 (ops 22-26)
I20260812 06:19:06.313479  2900 log.cc:1079] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/5c0253e2be5644b8a2f9230b6b76dff1/wal-000000006 (ops 27-31)
I20260812 06:19:06.313522  2900 log.cc:1079] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/5c0253e2be5644b8a2f9230b6b76dff1/wal-000000007 (ops 32-36)
I20260812 06:19:06.313588  2900 log.cc:1079] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/5c0253e2be5644b8a2f9230b6b76dff1/wal-000000008 (ops 37-41)
I20260812 06:19:06.313633  2900 log.cc:1079] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/5c0253e2be5644b8a2f9230b6b76dff1/wal-000000009 (ops 42-46)
I20260812 06:19:06.313678  2900 log.cc:1079] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/5c0253e2be5644b8a2f9230b6b76dff1/wal-000000010 (ops 47-51)
I20260812 06:19:06.313719  2900 log.cc:1079] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/5c0253e2be5644b8a2f9230b6b76dff1/wal-000000011 (ops 52-56)
I20260812 06:19:06.313757  2900 log.cc:1079] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/5c0253e2be5644b8a2f9230b6b76dff1/wal-000000012 (ops 57-61)
I20260812 06:19:06.313796  2900 log.cc:1079] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/5c0253e2be5644b8a2f9230b6b76dff1/wal-000000013 (ops 62-66)
I20260812 06:19:06.341305  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: LogGCOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:19:06.341950  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=3.181125
I20260812 06:19:06.362520  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.020s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7098,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:06.363019  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling UndoDeltaBlockGCOp(5c0253e2be5644b8a2f9230b6b76dff1): 447 bytes on disk
I20260812 06:19:06.363423  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: UndoDeltaBlockGCOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:19:06.363880  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=2.188937
I20260812 06:19:06.373864  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3692,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:06.374302  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling MajorDeltaCompactionOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=1.000000
I20260812 06:19:06.598184  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: MajorDeltaCompactionOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.224s	user 0.133s	sys 0.081s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979849,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":601,"lbm_read_time_us":15852,"lbm_reads_lt_1ms":775,"lbm_write_time_us":40470,"lbm_writes_lt_1ms":743,"mutex_wait_us":668,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":18432,"thread_start_us":92,"threads_started":1,"update_count":3500}
I20260812 06:19:06.599050  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=18.063937
I20260812 06:19:06.667521  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.068s	user 0.042s	sys 0.024s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":30267,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:06.668057  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=2.188937
I20260812 06:19:06.679095  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3879,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.679713  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling MajorDeltaCompactionOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=1.000000
I20260812 06:19:06.849889  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: MajorDeltaCompactionOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.170s	user 0.149s	sys 0.020s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877104,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":335,"lbm_read_time_us":11928,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34071,"lbm_writes_lt_1ms":643,"mutex_wait_us":32,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":3000}
I20260812 06:19:06.850598  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=14.095187
I20260812 06:19:06.900766  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.050s	user 0.039s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21023,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:06.901489  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=3.181125
I20260812 06:19:06.926666  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.025s	user 0.018s	sys 0.000s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7096,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:06.927201  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=2.188937
I20260812 06:19:06.936925  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3559,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:06.937409  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling MajorDeltaCompactionOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=1.000000
I20260812 06:19:07.115438  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: MajorDeltaCompactionOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.178s	user 0.142s	sys 0.036s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877206,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":989,"lbm_read_time_us":15470,"lbm_reads_lt_1ms":673,"lbm_write_time_us":34335,"lbm_writes_lt_1ms":643,"mutex_wait_us":322,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":23552,"update_count":3000}
I20260812 06:19:07.115994  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=14.095187
I20260812 06:19:07.169351  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.053s	user 0.033s	sys 0.017s Metrics: {"bytes_written":16409914,"delete_count":0,"lbm_write_time_us":23767,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:07.169888  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=2.188937
I20260812 06:19:07.180677  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3971,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.181298  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling MajorDeltaCompactionOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=1.000000
I20260812 06:19:07.331578  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: MajorDeltaCompactionOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.150s	user 0.115s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774701,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":320,"lbm_read_time_us":9953,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29254,"lbm_writes_lt_1ms":543,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":21248,"update_count":2500}
I20260812 06:19:07.332324  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=11.118625
I20260812 06:19:07.374748  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.042s	user 0.026s	sys 0.016s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":19028,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:07.375236  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=2.188937
I20260812 06:19:07.387403  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4682,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:07.388015  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling MajorDeltaCompactionOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=1.000000
I20260812 06:19:07.532634  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: MajorDeltaCompactionOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.144s	user 0.081s	sys 0.061s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672270,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":194,"lbm_read_time_us":11150,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23818,"lbm_writes_lt_1ms":443,"mutex_wait_us":74,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":2000}
I20260812 06:19:07.533324  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=11.118625
I20260812 06:19:07.571264  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.038s	user 0.014s	sys 0.023s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16191,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:07.571789  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=2.188937
I20260812 06:19:07.598052  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.026s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5334,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:07.598675  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=2.188937
I20260812 06:19:07.618423  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.020s	user 0.004s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4061,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.619047  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushMRSOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=1.000000
I20260812 06:19:07.660596  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushMRSOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.041s	user 0.026s	sys 0.005s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":239,"dirs.run_wall_time_us":1239,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1424,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:07.661695  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling LogGCOp(5c0253e2be5644b8a2f9230b6b76dff1): free 112239316 bytes of WAL
I20260812 06:19:07.661999  2900 log_reader.cc:385] T 5c0253e2be5644b8a2f9230b6b76dff1: removed 11 log segments from log reader
I20260812 06:19:07.662050  2900 log.cc:1079] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/5c0253e2be5644b8a2f9230b6b76dff1/wal-000000014 (ops 67-71)
I20260812 06:19:07.662096  2900 log.cc:1079] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/5c0253e2be5644b8a2f9230b6b76dff1/wal-000000015 (ops 72-76)
I20260812 06:19:07.662150  2900 log.cc:1079] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/5c0253e2be5644b8a2f9230b6b76dff1/wal-000000016 (ops 77-81)
I20260812 06:19:07.662222  2900 log.cc:1079] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/5c0253e2be5644b8a2f9230b6b76dff1/wal-000000017 (ops 82-86)
I20260812 06:19:07.662262  2900 log.cc:1079] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/5c0253e2be5644b8a2f9230b6b76dff1/wal-000000018 (ops 87-91)
I20260812 06:19:07.662324  2900 log.cc:1079] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/5c0253e2be5644b8a2f9230b6b76dff1/wal-000000019 (ops 92-96)
I20260812 06:19:07.662364  2900 log.cc:1079] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/5c0253e2be5644b8a2f9230b6b76dff1/wal-000000020 (ops 97-101)
I20260812 06:19:07.662406  2900 log.cc:1079] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/5c0253e2be5644b8a2f9230b6b76dff1/wal-000000021 (ops 102-106)
I20260812 06:19:07.662451  2900 log.cc:1079] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/5c0253e2be5644b8a2f9230b6b76dff1/wal-000000022 (ops 107-111)
I20260812 06:19:07.662525  2900 log.cc:1079] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/5c0253e2be5644b8a2f9230b6b76dff1/wal-000000023 (ops 112-116)
I20260812 06:19:07.662571  2900 log.cc:1079] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/5c0253e2be5644b8a2f9230b6b76dff1/wal-000000024 (ops 117-120)
I20260812 06:19:07.689327  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: LogGCOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.027s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:19:07.689800  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=3.181125
I20260812 06:19:07.716888  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.027s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4828,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:07.717468  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=2.188937
I20260812 06:19:07.731004  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5107,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:07.731515  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling MajorDeltaCompactionOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=1.000000
I20260812 06:19:07.983400  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: MajorDeltaCompactionOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.252s	user 0.168s	sys 0.075s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979848,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":582,"lbm_read_time_us":15619,"lbm_reads_lt_1ms":775,"lbm_write_time_us":41784,"lbm_writes_lt_1ms":743,"mutex_wait_us":86,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":85,"threads_started":1,"update_count":3500}
I20260812 06:19:07.984241  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=18.063937
I20260812 06:19:08.056849  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.072s	user 0.049s	sys 0.015s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":29811,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:08.057327  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling UndoDeltaBlockGCOp(5c0253e2be5644b8a2f9230b6b76dff1): 447 bytes on disk
I20260812 06:19:08.057756  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: UndoDeltaBlockGCOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:19:08.058357  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=2.188937
I20260812 06:19:08.069793  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3880,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:08.070379  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling MajorDeltaCompactionOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=1.000000
I20260812 06:19:08.266494  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: MajorDeltaCompactionOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.196s	user 0.145s	sys 0.048s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877105,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":824,"lbm_read_time_us":13051,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33734,"lbm_writes_lt_1ms":643,"mutex_wait_us":375,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":31104,"update_count":3000}
I20260812 06:19:08.267728  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=16.079562
I20260812 06:19:08.340658  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.073s	user 0.040s	sys 0.019s Metrics: {"bytes_written":17599603,"delete_count":0,"lbm_write_time_us":28812,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":431,"reinsert_count":0,"update_count":2145}
I20260812 06:19:08.341152  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=5.165500
I20260812 06:19:08.361308  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.020s	user 0.013s	sys 0.004s Metrics: {"bytes_written":7015381,"delete_count":0,"lbm_write_time_us":7951,"lbm_writes_lt_1ms":174,"reinsert_count":0,"update_count":855}
I20260812 06:19:08.361907  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling MajorDeltaCompactionOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=1.000000
I20260812 06:19:08.568689  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: MajorDeltaCompactionOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.207s	user 0.132s	sys 0.070s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877106,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":264,"lbm_read_time_us":14115,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35360,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13568,"update_count":3000}
I20260812 06:19:08.569531  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=15.087375
I20260812 06:19:08.611487  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.042s	user 0.029s	sys 0.011s Metrics: {"bytes_written":17476528,"delete_count":0,"lbm_write_time_us":19063,"lbm_writes_lt_1ms":429,"reinsert_count":0,"update_count":2130}
I20260812 06:19:08.612150  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=1.196750
I20260812 06:19:08.633070  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.021s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3036005,"delete_count":0,"lbm_write_time_us":4193,"lbm_writes_lt_1ms":77,"mutex_wait_us":20,"reinsert_count":0,"update_count":370}
I20260812 06:19:08.633587  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=2.188937
I20260812 06:19:08.644287  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4145,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:08.644723  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling MajorDeltaCompactionOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=1.000000
I20260812 06:19:08.855402  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: MajorDeltaCompactionOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.211s	user 0.143s	sys 0.067s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877192,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":755,"lbm_read_time_us":14140,"lbm_reads_lt_1ms":673,"lbm_write_time_us":36561,"lbm_writes_lt_1ms":643,"mutex_wait_us":278,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":3000}
I20260812 06:19:08.856103  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=15.087375
I20260812 06:19:08.894055  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.038s	user 0.029s	sys 0.005s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":16919,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:08.894884  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=2.188937
I20260812 06:19:08.912425  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.017s	user 0.011s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5900,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:08.913014  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling MajorDeltaCompactionOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=1.000000
I20260812 06:19:09.100335  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: MajorDeltaCompactionOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.187s	user 0.126s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774675,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":249,"lbm_read_time_us":11484,"lbm_reads_lt_1ms":564,"lbm_write_time_us":35566,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":31,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":2500}
I20260812 06:19:09.101058  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=15.087375
I20260812 06:19:09.152673  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.051s	user 0.022s	sys 0.027s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":23424,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:09.153254  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=2.188937
I20260812 06:19:09.176012  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.023s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5115,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:09.176512  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=2.188937
I20260812 06:19:09.187214  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4060,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:09.187763  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushMRSOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=1.000000
I20260812 06:19:09.222630  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushMRSOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.035s	user 0.034s	sys 0.000s Metrics: {"bytes_written":1275445,"cfile_init":1,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":331,"dirs.run_wall_time_us":1556,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2140,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:09.223430  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling LogGCOp(5c0253e2be5644b8a2f9230b6b76dff1): free 129320704 bytes of WAL
I20260812 06:19:09.223716  2900 log_reader.cc:385] T 5c0253e2be5644b8a2f9230b6b76dff1: removed 13 log segments from log reader
I20260812 06:19:09.223789  2900 log.cc:1079] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/5c0253e2be5644b8a2f9230b6b76dff1/wal-000000025 (ops 121-125)
I20260812 06:19:09.223831  2900 log.cc:1079] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/5c0253e2be5644b8a2f9230b6b76dff1/wal-000000026 (ops 126-130)
I20260812 06:19:09.223862  2900 log.cc:1079] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/5c0253e2be5644b8a2f9230b6b76dff1/wal-000000027 (ops 131-135)
I20260812 06:19:09.223891  2900 log.cc:1079] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/5c0253e2be5644b8a2f9230b6b76dff1/wal-000000028 (ops 136-140)
I20260812 06:19:09.223922  2900 log.cc:1079] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/5c0253e2be5644b8a2f9230b6b76dff1/wal-000000029 (ops 141-144)
I20260812 06:19:09.223954  2900 log.cc:1079] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/5c0253e2be5644b8a2f9230b6b76dff1/wal-000000030 (ops 145-149)
I20260812 06:19:09.223982  2900 log.cc:1079] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/5c0253e2be5644b8a2f9230b6b76dff1/wal-000000031 (ops 150-154)
I20260812 06:19:09.224009  2900 log.cc:1079] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/5c0253e2be5644b8a2f9230b6b76dff1/wal-000000032 (ops 155-159)
I20260812 06:19:09.224031  2900 log.cc:1079] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/5c0253e2be5644b8a2f9230b6b76dff1/wal-000000033 (ops 160-164)
I20260812 06:19:09.224061  2900 log.cc:1079] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/5c0253e2be5644b8a2f9230b6b76dff1/wal-000000034 (ops 165-168)
I20260812 06:19:09.224087  2900 log.cc:1079] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/5c0253e2be5644b8a2f9230b6b76dff1/wal-000000035 (ops 169-173)
I20260812 06:19:09.224112  2900 log.cc:1079] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/5c0253e2be5644b8a2f9230b6b76dff1/wal-000000036 (ops 174-178)
I20260812 06:19:09.224140  2900 log.cc:1079] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: Deleting log segment in path: /tmp/dist-test-taskoWxGhW/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515538825727-2475-0/minicluster-data/ts-0-root/wals/5c0253e2be5644b8a2f9230b6b76dff1/wal-000000037 (ops 179-183)
I20260812 06:19:09.254657  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: LogGCOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.031s	user 0.001s	sys 0.030s Metrics: {}
I20260812 06:19:09.255074  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=2.188937
I20260812 06:19:09.275076  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.020s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4498,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:09.275671  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling UndoDeltaBlockGCOp(5c0253e2be5644b8a2f9230b6b76dff1): 483 bytes on disk
I20260812 06:19:09.276111  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: UndoDeltaBlockGCOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:19:09.276736  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=2.188937
I20260812 06:19:09.287823  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4188,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:09.288568  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling MajorDeltaCompactionOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=1.000000
I20260812 06:19:09.523635  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: MajorDeltaCompactionOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.235s	user 0.155s	sys 0.080s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37082267,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":381,"lbm_read_time_us":17229,"lbm_reads_lt_1ms":875,"lbm_write_time_us":43213,"lbm_writes_lt_1ms":843,"mutex_wait_us":118,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":24064,"thread_start_us":81,"threads_started":1,"update_count":4000}
I20260812 06:19:09.524494  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=18.063937
I20260812 06:19:09.596563  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.072s	user 0.048s	sys 0.020s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":32494,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:19:09.597433  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=2.188937
I20260812 06:19:09.618089  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: FlushDeltaMemStoresOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.020s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6837,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:09.618769  2996 maintenance_manager.cc:419] P 2306b0e15d484b55b30bddb0c99d621d: Scheduling MajorDeltaCompactionOp(5c0253e2be5644b8a2f9230b6b76dff1): perf score=1.000000
I20260812 06:19:09.629510  2475 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.876s	user 1.796s	sys 0.156s
I20260812 06:19:09.687145  2475 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.057s	user 0.002s	sys 0.000s
I20260812 06:19:09.687708  2475 tablet_server.cc:179] TabletServer@127.2.106.193:0 shutting down...
I20260812 06:19:09.772122  2900 maintenance_manager.cc:643] P 2306b0e15d484b55b30bddb0c99d621d: MajorDeltaCompactionOp(5c0253e2be5644b8a2f9230b6b76dff1) complete. Timing: real 0.153s	user 0.097s	sys 0.055s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":365,"lbm_read_time_us":11168,"lbm_reads_lt_1ms":660,"lbm_write_time_us":31751,"lbm_writes_lt_1ms":643,"mutex_wait_us":60,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":35712,"update_count":3000}
I20260812 06:19:09.772848  2475 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:09.773314  2475 tablet_replica.cc:333] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d: stopping tablet replica
I20260812 06:19:09.773491  2475 raft_consensus.cc:2243] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:09.773696  2475 raft_consensus.cc:2272] T 5c0253e2be5644b8a2f9230b6b76dff1 P 2306b0e15d484b55b30bddb0c99d621d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:09.779487  2475 tablet_server.cc:196] TabletServer@127.2.106.193:0 shutdown complete.
I20260812 06:19:09.824612  2475 master.cc:562] Master@127.2.106.254:41259 shutting down...
I20260812 06:19:09.828475  2475 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 57ffc59dc4f04625a35a092bea105331 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:09.828719  2475 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 57ffc59dc4f04625a35a092bea105331 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:09.828816  2475 tablet_replica.cc:333] T 00000000000000000000000000000000 P 57ffc59dc4f04625a35a092bea105331: stopping tablet replica
I20260812 06:19:09.841639  2475 master.cc:584] Master@127.2.106.254:41259 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5440 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11110 ms total)

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