[==========] 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:38.494781  4547 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.4.112.254:38451
I20260812 06:18:38.495766  4547 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:38.496358  4547 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:18:38.502429  4547 server_base.cc:1061] running on GCE node
W20260812 06:18:38.502374  4566 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:38.502578  4558 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:38.502619  4559 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:38.503084  4547 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:38.503183  4547 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:38.503221  4547 hybrid_clock.cc:648] HybridClock initialized: now 1786515518503219 us; error 0 us; skew 500 ppm
I20260812 06:18:38.504902  4547 webserver.cc:533] Webserver started at http://127.4.112.254:41843/ using document root <none> and password file <none>
I20260812 06:18:38.505407  4547 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:38.505462  4547 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:38.505661  4547 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:38.507319  4547 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/master-0-root/instance:
uuid: "86acdfe2b94c461e803cceff3c6c8cb4"
format_stamp: "Formatted at 2026-08-12 06:18:38 on dist-test-slave-4tdj"
I20260812 06:18:38.510715  4547 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:18:38.512724  4573 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:38.513681  4547 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:38.513789  4547 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/master-0-root
uuid: "86acdfe2b94c461e803cceff3c6c8cb4"
format_stamp: "Formatted at 2026-08-12 06:18:38 on dist-test-slave-4tdj"
I20260812 06:18:38.513875  4547 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-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:38.538695  4547 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:38.539367  4547 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:38.539530  4547 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:38.546751  4652 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.4.112.254:38451 every 8 connection(s)
I20260812 06:18:38.546748  4547 rpc_server.cc:307] RPC server started. Bound to: 127.4.112.254:38451
I20260812 06:18:38.548949  4656 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:38.554039  4656 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 86acdfe2b94c461e803cceff3c6c8cb4: Bootstrap starting.
I20260812 06:18:38.556311  4656 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 86acdfe2b94c461e803cceff3c6c8cb4: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:38.557125  4656 log.cc:826] T 00000000000000000000000000000000 P 86acdfe2b94c461e803cceff3c6c8cb4: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:38.558733  4656 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 86acdfe2b94c461e803cceff3c6c8cb4: No bootstrap required, opened a new log
I20260812 06:18:38.561390  4656 raft_consensus.cc:359] T 00000000000000000000000000000000 P 86acdfe2b94c461e803cceff3c6c8cb4 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "86acdfe2b94c461e803cceff3c6c8cb4" member_type: VOTER }
I20260812 06:18:38.561548  4656 raft_consensus.cc:385] T 00000000000000000000000000000000 P 86acdfe2b94c461e803cceff3c6c8cb4 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:38.561594  4656 raft_consensus.cc:740] T 00000000000000000000000000000000 P 86acdfe2b94c461e803cceff3c6c8cb4 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 86acdfe2b94c461e803cceff3c6c8cb4, State: Initialized, Role: FOLLOWER
I20260812 06:18:38.562096  4656 consensus_queue.cc:260] T 00000000000000000000000000000000 P 86acdfe2b94c461e803cceff3c6c8cb4 [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: "86acdfe2b94c461e803cceff3c6c8cb4" member_type: VOTER }
I20260812 06:18:38.562228  4656 raft_consensus.cc:399] T 00000000000000000000000000000000 P 86acdfe2b94c461e803cceff3c6c8cb4 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:38.562274  4656 raft_consensus.cc:493] T 00000000000000000000000000000000 P 86acdfe2b94c461e803cceff3c6c8cb4 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:38.562402  4656 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 86acdfe2b94c461e803cceff3c6c8cb4 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:38.563148  4656 raft_consensus.cc:515] T 00000000000000000000000000000000 P 86acdfe2b94c461e803cceff3c6c8cb4 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "86acdfe2b94c461e803cceff3c6c8cb4" member_type: VOTER }
I20260812 06:18:38.563560  4656 leader_election.cc:304] T 00000000000000000000000000000000 P 86acdfe2b94c461e803cceff3c6c8cb4 [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: 86acdfe2b94c461e803cceff3c6c8cb4; no voters: 
I20260812 06:18:38.563843  4656 leader_election.cc:290] T 00000000000000000000000000000000 P 86acdfe2b94c461e803cceff3c6c8cb4 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:38.563951  4663 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 86acdfe2b94c461e803cceff3c6c8cb4 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:38.564186  4663 raft_consensus.cc:697] T 00000000000000000000000000000000 P 86acdfe2b94c461e803cceff3c6c8cb4 [term 1 LEADER]: Becoming Leader. State: Replica: 86acdfe2b94c461e803cceff3c6c8cb4, State: Running, Role: LEADER
I20260812 06:18:38.564647  4663 consensus_queue.cc:237] T 00000000000000000000000000000000 P 86acdfe2b94c461e803cceff3c6c8cb4 [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: "86acdfe2b94c461e803cceff3c6c8cb4" member_type: VOTER }
I20260812 06:18:38.564823  4656 sys_catalog.cc:565] T 00000000000000000000000000000000 P 86acdfe2b94c461e803cceff3c6c8cb4 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:38.566569  4664 sys_catalog.cc:455] T 00000000000000000000000000000000 P 86acdfe2b94c461e803cceff3c6c8cb4 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "86acdfe2b94c461e803cceff3c6c8cb4" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "86acdfe2b94c461e803cceff3c6c8cb4" member_type: VOTER } }
I20260812 06:18:38.566694  4664 sys_catalog.cc:458] T 00000000000000000000000000000000 P 86acdfe2b94c461e803cceff3c6c8cb4 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:38.566560  4665 sys_catalog.cc:455] T 00000000000000000000000000000000 P 86acdfe2b94c461e803cceff3c6c8cb4 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 86acdfe2b94c461e803cceff3c6c8cb4. Latest consensus state: current_term: 1 leader_uuid: "86acdfe2b94c461e803cceff3c6c8cb4" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "86acdfe2b94c461e803cceff3c6c8cb4" member_type: VOTER } }
I20260812 06:18:38.566918  4665 sys_catalog.cc:458] T 00000000000000000000000000000000 P 86acdfe2b94c461e803cceff3c6c8cb4 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:38.566948  4547 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:38.567165  4689 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:38.569310  4689 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:38.573513  4689 catalog_manager.cc:1383] Generated new cluster ID: d23ff82071084a358839bce5a7427137
I20260812 06:18:38.573578  4689 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:38.595525  4689 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:38.596446  4689 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:38.603039  4689 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 86acdfe2b94c461e803cceff3c6c8cb4: Generated new TSK 0
I20260812 06:18:38.603709  4689 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:38.631853  4547 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:38.634961  4697 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:38.634927  4699 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:38.635078  4704 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:38.635176  4547 server_base.cc:1061] running on GCE node
I20260812 06:18:38.635493  4547 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:38.635540  4547 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:38.635555  4547 hybrid_clock.cc:648] HybridClock initialized: now 1786515518635554 us; error 0 us; skew 500 ppm
I20260812 06:18:38.636437  4547 webserver.cc:533] Webserver started at http://127.4.112.193:32791/ using document root <none> and password file <none>
I20260812 06:18:38.636610  4547 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:38.636660  4547 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:38.636750  4547 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:38.637126  4547 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root/instance:
uuid: "9d84c50bb626416ba517feb8cab3c44b"
format_stamp: "Formatted at 2026-08-12 06:18:38 on dist-test-slave-4tdj"
I20260812 06:18:38.638592  4547 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:38.639518  4716 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:38.639767  4547 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:38.639835  4547 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root
uuid: "9d84c50bb626416ba517feb8cab3c44b"
format_stamp: "Formatted at 2026-08-12 06:18:38 on dist-test-slave-4tdj"
I20260812 06:18:38.639909  4547 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-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:38.654721  4547 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:38.655381  4547 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:38.655880  4547 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:38.656738  4547 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:38.656792  4547 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:38.656840  4547 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:38.656869  4547 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:38.662824  4547 rpc_server.cc:307] RPC server started. Bound to: 127.4.112.193:37073
I20260812 06:18:38.663019  4819 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.4.112.193:37073 every 8 connection(s)
I20260812 06:18:38.674963  4821 heartbeater.cc:344] Connected to a master server at 127.4.112.254:38451
I20260812 06:18:38.675177  4821 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:38.675596  4821 heartbeater.cc:507] Master 127.4.112.254:38451 requested a full tablet report, sending...
I20260812 06:18:38.676951  4599 ts_manager.cc:194] Registered new tserver with Master: 9d84c50bb626416ba517feb8cab3c44b (127.4.112.193:37073)
I20260812 06:18:38.677044  4547 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013561562s
I20260812 06:18:38.678124  4599 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:55524
I20260812 06:18:38.687085  4599 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:55536:
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:38.700330  4772 tablet_service.cc:1511] Processing CreateTablet for tablet 1bda1a73ef454c39b18f543b49dda163 (DEFAULT_TABLE table=heavy-update-compaction-test [id=f64ddc7b709142eaaa748e3cc2a9be8f]), partition=
I20260812 06:18:38.700785  4772 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 1bda1a73ef454c39b18f543b49dda163. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:38.702926  4841 tablet_bootstrap.cc:492] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Bootstrap starting.
I20260812 06:18:38.704303  4841 tablet_bootstrap.cc:654] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:38.705468  4841 tablet_bootstrap.cc:492] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: No bootstrap required, opened a new log
I20260812 06:18:38.705556  4841 ts_tablet_manager.cc:1403] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:38.705967  4841 raft_consensus.cc:359] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9d84c50bb626416ba517feb8cab3c44b" member_type: VOTER last_known_addr { host: "127.4.112.193" port: 37073 } }
I20260812 06:18:38.706071  4841 raft_consensus.cc:385] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:38.706095  4841 raft_consensus.cc:740] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 9d84c50bb626416ba517feb8cab3c44b, State: Initialized, Role: FOLLOWER
I20260812 06:18:38.706219  4841 consensus_queue.cc:260] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b [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: "9d84c50bb626416ba517feb8cab3c44b" member_type: VOTER last_known_addr { host: "127.4.112.193" port: 37073 } }
I20260812 06:18:38.706318  4841 raft_consensus.cc:399] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:38.706364  4841 raft_consensus.cc:493] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:38.706413  4841 raft_consensus.cc:3060] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:38.707062  4841 raft_consensus.cc:515] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9d84c50bb626416ba517feb8cab3c44b" member_type: VOTER last_known_addr { host: "127.4.112.193" port: 37073 } }
I20260812 06:18:38.707211  4841 leader_election.cc:304] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b [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: 9d84c50bb626416ba517feb8cab3c44b; no voters: 
I20260812 06:18:38.707605  4841 leader_election.cc:290] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:38.707957  4841 ts_tablet_manager.cc:1434] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:38.708397  4821 heartbeater.cc:499] Master 127.4.112.254:38451 was elected leader, sending a full tablet report...
I20260812 06:18:38.708437  4854 raft_consensus.cc:2804] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:38.708599  4854 raft_consensus.cc:697] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b [term 1 LEADER]: Becoming Leader. State: Replica: 9d84c50bb626416ba517feb8cab3c44b, State: Running, Role: LEADER
I20260812 06:18:38.708729  4854 consensus_queue.cc:237] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b [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: "9d84c50bb626416ba517feb8cab3c44b" member_type: VOTER last_known_addr { host: "127.4.112.193" port: 37073 } }
I20260812 06:18:38.711504  4599 catalog_manager.cc:5719] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b reported cstate change: term changed from 0 to 1, leader changed from <none> to 9d84c50bb626416ba517feb8cab3c44b (127.4.112.193). New cstate: current_term: 1 leader_uuid: "9d84c50bb626416ba517feb8cab3c44b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9d84c50bb626416ba517feb8cab3c44b" member_type: VOTER last_known_addr { host: "127.4.112.193" port: 37073 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:38.786279  4547 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.061s	user 0.026s	sys 0.003s
I20260812 06:18:38.913952  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushMRSOp(1bda1a73ef454c39b18f543b49dda163): perf score=15.086190
I20260812 06:18:39.084026  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushMRSOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.170s	user 0.121s	sys 0.040s Metrics: {"bytes_written":12553635,"cfile_init":1,"compiler_manager_pool.queue_time_us":179,"delete_count":0,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":165,"dirs.run_wall_time_us":904,"drs_written":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42820,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":672,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":201088,"thread_start_us":91,"threads_started":1,"update_count":1530}
I20260812 06:18:39.085335  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling LogGCOp(1bda1a73ef454c39b18f543b49dda163): free 20743880 bytes of WAL
I20260812 06:18:39.085654  4727 log_reader.cc:385] T 1bda1a73ef454c39b18f543b49dda163: removed 2 log segments from log reader
I20260812 06:18:39.085737  4727 log.cc:1079] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/1bda1a73ef454c39b18f543b49dda163/wal-000000001 (ops 1-6)
I20260812 06:18:39.085808  4727 log.cc:1079] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/1bda1a73ef454c39b18f543b49dda163/wal-000000002 (ops 7-11)
I20260812 06:18:39.090812  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: LogGCOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.005s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:18:39.091277  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=2.188937
I20260812 06:18:39.108451  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.017s	user 0.007s	sys 0.006s Metrics: {"bytes_written":4102663,"delete_count":0,"lbm_write_time_us":6277,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.108953  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=2.188937
I20260812 06:18:39.122488  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.013s	user 0.002s	sys 0.011s Metrics: {"bytes_written":3446255,"delete_count":0,"lbm_write_time_us":4908,"lbm_writes_lt_1ms":87,"reinsert_count":0,"update_count":420}
I20260812 06:18:39.122946  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling UndoDeltaBlockGCOp(1bda1a73ef454c39b18f543b49dda163): 12719214 bytes on disk
I20260812 06:18:39.123553  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: UndoDeltaBlockGCOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4}
I20260812 06:18:39.123992  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling MajorDeltaCompactionOp(1bda1a73ef454c39b18f543b49dda163): perf score=1.000000
I20260812 06:18:39.275218  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: MajorDeltaCompactionOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.151s	user 0.100s	sys 0.049s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24364553,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":573,"lbm_read_time_us":12234,"lbm_reads_lt_1ms":559,"lbm_write_time_us":26030,"lbm_writes_lt_1ms":533,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":5504,"thread_start_us":287,"threads_started":5,"update_count":2450}
I20260812 06:18:39.275722  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=10.126437
I20260812 06:18:39.311226  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.035s	user 0.015s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14072,"lbm_writes_lt_1ms":303,"mutex_wait_us":2,"reinsert_count":0,"update_count":1500}
I20260812 06:18:39.311636  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=2.188937
I20260812 06:18:39.323365  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4424,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.324041  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling MajorDeltaCompactionOp(1bda1a73ef454c39b18f543b49dda163): perf score=1.000000
I20260812 06:18:39.450603  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: MajorDeltaCompactionOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.126s	user 0.101s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":304,"lbm_read_time_us":9322,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23399,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":2000}
I20260812 06:18:39.451095  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=10.126437
I20260812 06:18:39.489719  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.038s	user 0.020s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13425,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:39.490242  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=2.188937
I20260812 06:18:39.505486  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5381,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.506110  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling MajorDeltaCompactionOp(1bda1a73ef454c39b18f543b49dda163): perf score=1.000000
I20260812 06:18:39.626961  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: MajorDeltaCompactionOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.121s	user 0.099s	sys 0.021s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":258,"lbm_read_time_us":8568,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24088,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12160,"update_count":2000}
I20260812 06:18:39.627889  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=10.126437
I20260812 06:18:39.672273  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.044s	user 0.025s	sys 0.014s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14497,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:39.672784  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=2.188937
I20260812 06:18:39.683005  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3837,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.683413  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling MajorDeltaCompactionOp(1bda1a73ef454c39b18f543b49dda163): perf score=1.000000
I20260812 06:18:39.824154  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: MajorDeltaCompactionOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.141s	user 0.086s	sys 0.054s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":549,"lbm_read_time_us":10451,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23803,"lbm_writes_lt_1ms":443,"mutex_wait_us":344,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2000}
I20260812 06:18:39.824605  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=10.126437
I20260812 06:18:39.856153  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.031s	user 0.016s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":13266,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:39.856751  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling MajorDeltaCompactionOp(1bda1a73ef454c39b18f543b49dda163): perf score=1.000000
I20260812 06:18:39.968184  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: MajorDeltaCompactionOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.111s	user 0.079s	sys 0.031s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569748,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":646,"lbm_read_time_us":6235,"lbm_reads_lt_1ms":363,"lbm_write_time_us":21177,"lbm_writes_lt_1ms":343,"mutex_wait_us":289,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":15360,"update_count":1500}
I20260812 06:18:39.968868  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=10.126437
I20260812 06:18:40.011411  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.042s	user 0.029s	sys 0.009s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15743,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:40.011904  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=2.188937
I20260812 06:18:40.021795  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3580,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.022377  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling MajorDeltaCompactionOp(1bda1a73ef454c39b18f543b49dda163): perf score=1.000000
I20260812 06:18:40.136989  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: MajorDeltaCompactionOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.114s	user 0.085s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":238,"lbm_read_time_us":9164,"lbm_reads_lt_1ms":472,"lbm_write_time_us":19852,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2000}
I20260812 06:18:40.137662  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=10.126437
I20260812 06:18:40.185364  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.048s	user 0.012s	sys 0.030s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16337,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:40.185945  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=2.188937
I20260812 06:18:40.200165  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.014s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5578,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.200719  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling MajorDeltaCompactionOp(1bda1a73ef454c39b18f543b49dda163): perf score=1.000000
I20260812 06:18:40.335983  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: MajorDeltaCompactionOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.135s	user 0.102s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":630,"lbm_read_time_us":10625,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20778,"lbm_writes_lt_1ms":443,"mutex_wait_us":68,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:40.336570  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=10.126437
I20260812 06:18:40.377601  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.041s	user 0.024s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12719,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":1500}
I20260812 06:18:40.378132  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=2.188937
I20260812 06:18:40.393146  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.015s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5480,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.393680  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushMRSOp(1bda1a73ef454c39b18f543b49dda163): perf score=1.000000
I20260812 06:18:40.420451  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushMRSOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.027s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":261,"dirs.run_wall_time_us":1512,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1467,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:40.421211  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling LogGCOp(1bda1a73ef454c39b18f543b49dda163): free 124710309 bytes of WAL
I20260812 06:18:40.421427  4727 log_reader.cc:385] T 1bda1a73ef454c39b18f543b49dda163: removed 12 log segments from log reader
I20260812 06:18:40.421470  4727 log.cc:1079] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/1bda1a73ef454c39b18f543b49dda163/wal-000000003 (ops 12-16)
I20260812 06:18:40.421499  4727 log.cc:1079] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/1bda1a73ef454c39b18f543b49dda163/wal-000000004 (ops 17-21)
I20260812 06:18:40.421530  4727 log.cc:1079] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/1bda1a73ef454c39b18f543b49dda163/wal-000000005 (ops 22-26)
I20260812 06:18:40.421561  4727 log.cc:1079] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/1bda1a73ef454c39b18f543b49dda163/wal-000000006 (ops 27-31)
I20260812 06:18:40.421591  4727 log.cc:1079] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/1bda1a73ef454c39b18f543b49dda163/wal-000000007 (ops 32-36)
I20260812 06:18:40.421622  4727 log.cc:1079] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/1bda1a73ef454c39b18f543b49dda163/wal-000000008 (ops 37-41)
I20260812 06:18:40.421653  4727 log.cc:1079] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/1bda1a73ef454c39b18f543b49dda163/wal-000000009 (ops 42-46)
I20260812 06:18:40.421684  4727 log.cc:1079] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/1bda1a73ef454c39b18f543b49dda163/wal-000000010 (ops 47-51)
I20260812 06:18:40.421710  4727 log.cc:1079] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/1bda1a73ef454c39b18f543b49dda163/wal-000000011 (ops 52-56)
I20260812 06:18:40.421732  4727 log.cc:1079] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/1bda1a73ef454c39b18f543b49dda163/wal-000000012 (ops 57-61)
I20260812 06:18:40.421763  4727 log.cc:1079] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/1bda1a73ef454c39b18f543b49dda163/wal-000000013 (ops 62-66)
I20260812 06:18:40.421793  4727 log.cc:1079] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/1bda1a73ef454c39b18f543b49dda163/wal-000000014 (ops 67-71)
I20260812 06:18:40.445839  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: LogGCOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.024s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:18:40.446341  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling UndoDeltaBlockGCOp(1bda1a73ef454c39b18f543b49dda163): 482 bytes on disk
I20260812 06:18:40.446774  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: UndoDeltaBlockGCOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:18:40.447232  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=3.181125
I20260812 06:18:40.460522  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.013s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4245,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:40.460987  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=2.188937
I20260812 06:18:40.477646  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.016s	user 0.004s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3359,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:40.478248  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling MajorDeltaCompactionOp(1bda1a73ef454c39b18f543b49dda163): perf score=1.000000
I20260812 06:18:40.667464  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: MajorDeltaCompactionOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.189s	user 0.123s	sys 0.064s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877328,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":118,"lbm_read_time_us":13740,"lbm_reads_lt_1ms":674,"lbm_write_time_us":29801,"lbm_writes_lt_1ms":643,"mutex_wait_us":37,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6144,"thread_start_us":70,"threads_started":1,"update_count":3000}
I20260812 06:18:40.667997  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=14.095187
I20260812 06:18:40.720721  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.053s	user 0.020s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16974,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:40.721215  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=2.188937
I20260812 06:18:40.731724  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3898,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.732131  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling MajorDeltaCompactionOp(1bda1a73ef454c39b18f543b49dda163): perf score=1.000000
I20260812 06:18:40.894582  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: MajorDeltaCompactionOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.162s	user 0.107s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":137,"lbm_read_time_us":11413,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27791,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:40.895519  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=10.126437
I20260812 06:18:40.940948  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.045s	user 0.025s	sys 0.015s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":19366,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":300,"reinsert_count":0,"update_count":1500}
I20260812 06:18:40.941529  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=2.188937
I20260812 06:18:40.963358  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.022s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5073,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.963829  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=2.188937
I20260812 06:18:40.973784  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3569,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.974236  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling MajorDeltaCompactionOp(1bda1a73ef454c39b18f543b49dda163): perf score=1.000000
I20260812 06:18:41.136008  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: MajorDeltaCompactionOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.162s	user 0.114s	sys 0.044s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774810,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":830,"lbm_read_time_us":9769,"lbm_reads_lt_1ms":573,"lbm_write_time_us":26964,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:41.136488  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=11.118625
I20260812 06:18:41.177037  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.040s	user 0.030s	sys 0.008s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":17922,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:18:41.177516  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=2.188937
I20260812 06:18:41.194005  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.016s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4246,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:41.194468  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=2.188937
I20260812 06:18:41.204119  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3513,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.204533  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling MajorDeltaCompactionOp(1bda1a73ef454c39b18f543b49dda163): perf score=1.000000
I20260812 06:18:41.337968  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: MajorDeltaCompactionOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.133s	user 0.088s	sys 0.044s 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":338,"lbm_read_time_us":9981,"lbm_reads_lt_1ms":573,"lbm_write_time_us":24852,"lbm_writes_lt_1ms":543,"mutex_wait_us":94,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:41.338919  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=10.126437
I20260812 06:18:41.374832  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.036s	user 0.015s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14983,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:41.375296  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=2.188937
I20260812 06:18:41.393623  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.018s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5120,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.394146  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling MajorDeltaCompactionOp(1bda1a73ef454c39b18f543b49dda163): perf score=1.000000
I20260812 06:18:41.513468  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: MajorDeltaCompactionOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.119s	user 0.099s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":156,"lbm_read_time_us":7071,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23905,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17152,"update_count":2000}
I20260812 06:18:41.513983  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=10.126437
I20260812 06:18:41.554111  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.040s	user 0.024s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18647,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:41.554721  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=2.188937
I20260812 06:18:41.580993  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.026s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4896,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.581471  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=2.188937
I20260812 06:18:41.596460  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.015s	user 0.001s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5364,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.596922  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling MajorDeltaCompactionOp(1bda1a73ef454c39b18f543b49dda163): perf score=1.000000
I20260812 06:18:41.739606  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: MajorDeltaCompactionOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.143s	user 0.100s	sys 0.042s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774807,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":198,"lbm_read_time_us":11781,"lbm_reads_lt_1ms":573,"lbm_write_time_us":24899,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":21376,"update_count":2500}
I20260812 06:18:41.740639  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=10.126437
I20260812 06:18:41.771201  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.030s	user 0.017s	sys 0.013s Metrics: {"bytes_written":12307508,"delete_count":0,"lbm_write_time_us":13034,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:41.771620  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=2.188937
I20260812 06:18:41.782476  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3928,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.782933  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushMRSOp(1bda1a73ef454c39b18f543b49dda163): perf score=1.000000
I20260812 06:18:41.814992  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushMRSOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.032s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":47,"dirs.run_cpu_time_us":162,"dirs.run_wall_time_us":1385,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1530,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:41.815702  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling LogGCOp(1bda1a73ef454c39b18f543b49dda163): free 121006445 bytes of WAL
I20260812 06:18:41.815930  4727 log_reader.cc:385] T 1bda1a73ef454c39b18f543b49dda163: removed 12 log segments from log reader
I20260812 06:18:41.815989  4727 log.cc:1079] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/1bda1a73ef454c39b18f543b49dda163/wal-000000015 (ops 72-76)
I20260812 06:18:41.816035  4727 log.cc:1079] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/1bda1a73ef454c39b18f543b49dda163/wal-000000016 (ops 77-81)
I20260812 06:18:41.816066  4727 log.cc:1079] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/1bda1a73ef454c39b18f543b49dda163/wal-000000017 (ops 82-86)
I20260812 06:18:41.816094  4727 log.cc:1079] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/1bda1a73ef454c39b18f543b49dda163/wal-000000018 (ops 87-90)
I20260812 06:18:41.816124  4727 log.cc:1079] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/1bda1a73ef454c39b18f543b49dda163/wal-000000019 (ops 91-95)
I20260812 06:18:41.816157  4727 log.cc:1079] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/1bda1a73ef454c39b18f543b49dda163/wal-000000020 (ops 96-100)
I20260812 06:18:41.816187  4727 log.cc:1079] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/1bda1a73ef454c39b18f543b49dda163/wal-000000021 (ops 101-105)
I20260812 06:18:41.816216  4727 log.cc:1079] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/1bda1a73ef454c39b18f543b49dda163/wal-000000022 (ops 106-110)
I20260812 06:18:41.816244  4727 log.cc:1079] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/1bda1a73ef454c39b18f543b49dda163/wal-000000023 (ops 111-115)
I20260812 06:18:41.816273  4727 log.cc:1079] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/1bda1a73ef454c39b18f543b49dda163/wal-000000024 (ops 116-120)
I20260812 06:18:41.816308  4727 log.cc:1079] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/1bda1a73ef454c39b18f543b49dda163/wal-000000025 (ops 121-125)
I20260812 06:18:41.816336  4727 log.cc:1079] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/1bda1a73ef454c39b18f543b49dda163/wal-000000026 (ops 126-130)
I20260812 06:18:41.842607  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: LogGCOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:41.843083  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=3.181125
I20260812 06:18:41.861816  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.019s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4512904,"delete_count":0,"lbm_write_time_us":4204,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:41.862249  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling LogGCOp(1bda1a73ef454c39b18f543b49dda163): free 11564893 bytes of WAL
I20260812 06:18:41.862460  4727 log_reader.cc:385] T 1bda1a73ef454c39b18f543b49dda163: removed 1 log segments from log reader
I20260812 06:18:41.862506  4727 log.cc:1079] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/1bda1a73ef454c39b18f543b49dda163/wal-000000027 (ops 131-134)
I20260812 06:18:41.864467  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: LogGCOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:41.864763  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=2.188937
I20260812 06:18:41.875262  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3599,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:41.875674  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling UndoDeltaBlockGCOp(1bda1a73ef454c39b18f543b49dda163): 472 bytes on disk
I20260812 06:18:41.876068  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: UndoDeltaBlockGCOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:18:41.876583  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling MajorDeltaCompactionOp(1bda1a73ef454c39b18f543b49dda163): perf score=1.000000
I20260812 06:18:42.063453  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: MajorDeltaCompactionOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.187s	user 0.147s	sys 0.040s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877348,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":480,"lbm_read_time_us":12599,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35019,"lbm_writes_lt_1ms":643,"mutex_wait_us":47,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8064,"thread_start_us":69,"threads_started":1,"update_count":3000}
I20260812 06:18:42.064050  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=14.095187
I20260812 06:18:42.104506  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.040s	user 0.018s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17662,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:42.105142  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=2.188937
I20260812 06:18:42.120977  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.016s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5385,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.121678  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling MajorDeltaCompactionOp(1bda1a73ef454c39b18f543b49dda163): perf score=1.000000
I20260812 06:18:42.286480  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: MajorDeltaCompactionOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.165s	user 0.129s	sys 0.027s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":633,"lbm_read_time_us":9442,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28407,"lbm_writes_lt_1ms":543,"mutex_wait_us":328,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2500}
I20260812 06:18:42.287117  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=14.095187
I20260812 06:18:42.332880  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.045s	user 0.028s	sys 0.009s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18462,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:42.334585  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling MajorDeltaCompactionOp(1bda1a73ef454c39b18f543b49dda163): perf score=1.000000
I20260812 06:18:42.512276  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: MajorDeltaCompactionOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.178s	user 0.113s	sys 0.051s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":753,"lbm_read_time_us":11825,"lbm_reads_lt_1ms":467,"lbm_write_time_us":28282,"lbm_writes_lt_1ms":443,"mutex_wait_us":29,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2000}
I20260812 06:18:42.512823  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=14.095187
I20260812 06:18:42.556733  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.044s	user 0.024s	sys 0.013s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":17162,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:42.557178  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=2.188937
I20260812 06:18:42.568334  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3991,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.569059  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling MajorDeltaCompactionOp(1bda1a73ef454c39b18f543b49dda163): perf score=1.000000
I20260812 06:18:42.742664  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: MajorDeltaCompactionOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.173s	user 0.108s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":621,"lbm_read_time_us":11433,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27989,"lbm_writes_lt_1ms":543,"mutex_wait_us":51,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2500}
I20260812 06:18:42.743207  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=14.095187
I20260812 06:18:42.790041  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.047s	user 0.024s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19586,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:42.790655  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=2.188937
I20260812 06:18:42.801535  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3894,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.802089  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling MajorDeltaCompactionOp(1bda1a73ef454c39b18f543b49dda163): perf score=1.000000
I20260812 06:18:42.958163  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: MajorDeltaCompactionOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.156s	user 0.112s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":587,"dirs.run_cpu_time_us":475,"dirs.run_wall_time_us":2615,"lbm_read_time_us":10863,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29161,"lbm_writes_lt_1ms":543,"mutex_wait_us":258,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:18:42.958835  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=11.118625
I20260812 06:18:42.996744  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.038s	user 0.019s	sys 0.014s Metrics: {"bytes_written":13456167,"delete_count":0,"lbm_write_time_us":13357,"lbm_writes_lt_1ms":331,"mutex_wait_us":84,"reinsert_count":0,"update_count":1640}
I20260812 06:18:42.997390  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=2.188937
I20260812 06:18:43.013254  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.016s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3364209,"delete_count":0,"lbm_write_time_us":5394,"lbm_writes_lt_1ms":85,"reinsert_count":0,"update_count":410}
I20260812 06:18:43.013697  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=2.188937
I20260812 06:18:43.023917  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3680,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:43.024444  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling MajorDeltaCompactionOp(1bda1a73ef454c39b18f543b49dda163): perf score=1.000000
I20260812 06:18:43.170164  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: MajorDeltaCompactionOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.146s	user 0.106s	sys 0.036s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774781,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":333,"lbm_read_time_us":9907,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28767,"lbm_writes_lt_1ms":543,"mutex_wait_us":33,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:18:43.170748  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=11.118625
I20260812 06:18:43.212821  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.042s	user 0.021s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":19596,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:18:43.213348  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=2.188937
I20260812 06:18:43.224828  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4007,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.225260  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=2.188937
I20260812 06:18:43.234490  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.009s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3328,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:43.234938  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushMRSOp(1bda1a73ef454c39b18f543b49dda163): perf score=1.000000
I20260812 06:18:43.262795  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushMRSOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.028s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":258,"dirs.run_wall_time_us":1431,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1322,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:43.263533  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling LogGCOp(1bda1a73ef454c39b18f543b49dda163): free 121006700 bytes of WAL
I20260812 06:18:43.263773  4727 log_reader.cc:385] T 1bda1a73ef454c39b18f543b49dda163: removed 12 log segments from log reader
I20260812 06:18:43.263819  4727 log.cc:1079] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/1bda1a73ef454c39b18f543b49dda163/wal-000000028 (ops 135-139)
I20260812 06:18:43.263850  4727 log.cc:1079] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/1bda1a73ef454c39b18f543b49dda163/wal-000000029 (ops 140-144)
I20260812 06:18:43.263885  4727 log.cc:1079] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/1bda1a73ef454c39b18f543b49dda163/wal-000000030 (ops 145-148)
I20260812 06:18:43.263917  4727 log.cc:1079] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/1bda1a73ef454c39b18f543b49dda163/wal-000000031 (ops 149-153)
I20260812 06:18:43.263949  4727 log.cc:1079] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/1bda1a73ef454c39b18f543b49dda163/wal-000000032 (ops 154-158)
I20260812 06:18:43.263981  4727 log.cc:1079] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/1bda1a73ef454c39b18f543b49dda163/wal-000000033 (ops 159-163)
I20260812 06:18:43.264012  4727 log.cc:1079] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/1bda1a73ef454c39b18f543b49dda163/wal-000000034 (ops 164-168)
I20260812 06:18:43.264045  4727 log.cc:1079] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/1bda1a73ef454c39b18f543b49dda163/wal-000000035 (ops 169-173)
I20260812 06:18:43.264074  4727 log.cc:1079] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/1bda1a73ef454c39b18f543b49dda163/wal-000000036 (ops 174-178)
I20260812 06:18:43.264107  4727 log.cc:1079] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/1bda1a73ef454c39b18f543b49dda163/wal-000000037 (ops 179-183)
I20260812 06:18:43.264138  4727 log.cc:1079] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/1bda1a73ef454c39b18f543b49dda163/wal-000000038 (ops 184-188)
I20260812 06:18:43.264170  4727 log.cc:1079] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/1bda1a73ef454c39b18f543b49dda163/wal-000000039 (ops 189-193)
I20260812 06:18:43.286144  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: LogGCOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.022s	user 0.000s	sys 0.019s Metrics: {}
I20260812 06:18:43.286548  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling UndoDeltaBlockGCOp(1bda1a73ef454c39b18f543b49dda163): 483 bytes on disk
I20260812 06:18:43.286949  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: UndoDeltaBlockGCOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4}
I20260812 06:18:43.287473  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=3.181125
I20260812 06:18:43.306936  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.019s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6806,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:43.307305  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163): perf score=2.188937
I20260812 06:18:43.325701  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: FlushDeltaMemStoresOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.018s	user 0.004s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3275,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:43.326339  4822 maintenance_manager.cc:419] P 9d84c50bb626416ba517feb8cab3c44b: Scheduling MajorDeltaCompactionOp(1bda1a73ef454c39b18f543b49dda163): perf score=1.000000
I20260812 06:18:43.428053  4547 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.642s	user 1.689s	sys 0.125s
I20260812 06:18:43.526811  4547 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.098s	user 0.003s	sys 0.000s
I20260812 06:18:43.527377  4547 tablet_server.cc:179] TabletServer@127.4.112.193:0 shutting down...
I20260812 06:18:43.530862  4727 maintenance_manager.cc:643] P 9d84c50bb626416ba517feb8cab3c44b: MajorDeltaCompactionOp(1bda1a73ef454c39b18f543b49dda163) complete. Timing: real 0.204s	user 0.112s	sys 0.090s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979851,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":514,"lbm_read_time_us":18595,"lbm_reads_1-10_ms":2,"lbm_reads_lt_1ms":769,"lbm_write_time_us":30563,"lbm_writes_lt_1ms":743,"mutex_wait_us":74,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":62,"threads_started":1,"update_count":3500}
I20260812 06:18:43.534447  4547 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:43.534781  4547 tablet_replica.cc:333] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b: stopping tablet replica
I20260812 06:18:43.534993  4547 raft_consensus.cc:2243] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:43.535226  4547 raft_consensus.cc:2272] T 1bda1a73ef454c39b18f543b49dda163 P 9d84c50bb626416ba517feb8cab3c44b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:43.550931  4547 tablet_server.cc:196] TabletServer@127.4.112.193:0 shutdown complete.
I20260812 06:18:43.589092  4547 master.cc:562] Master@127.4.112.254:38451 shutting down...
I20260812 06:18:43.592417  4547 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 86acdfe2b94c461e803cceff3c6c8cb4 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:43.592600  4547 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 86acdfe2b94c461e803cceff3c6c8cb4 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:43.592679  4547 tablet_replica.cc:333] T 00000000000000000000000000000000 P 86acdfe2b94c461e803cceff3c6c8cb4: stopping tablet replica
I20260812 06:18:43.604889  4547 master.cc:584] Master@127.4.112.254:38451 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5185 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:43.693624  4547 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.4.112.254:37399
I20260812 06:18:43.694051  4547 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:43.696091  4886 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:43.696271  4890 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:43.696234  4887 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:43.696238  4547 server_base.cc:1061] running on GCE node
I20260812 06:18:43.696501  4547 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:43.696539  4547 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:43.696552  4547 hybrid_clock.cc:648] HybridClock initialized: now 1786515523696553 us; error 0 us; skew 500 ppm
I20260812 06:18:43.697331  4547 webserver.cc:533] Webserver started at http://127.4.112.254:36157/ using document root <none> and password file <none>
I20260812 06:18:43.697465  4547 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:43.697505  4547 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:43.697561  4547 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:43.697886  4547 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/master-0-root/instance:
uuid: "3300acf161ed477fb58579d993da6f57"
format_stamp: "Formatted at 2026-08-12 06:18:43 on dist-test-slave-4tdj"
I20260812 06:18:43.699491  4547 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:43.700344  4897 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:43.700564  4547 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:43.700632  4547 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/master-0-root
uuid: "3300acf161ed477fb58579d993da6f57"
format_stamp: "Formatted at 2026-08-12 06:18:43 on dist-test-slave-4tdj"
I20260812 06:18:43.700704  4547 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-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:43.706207  4547 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:43.706574  4547 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:43.710547  4547 rpc_server.cc:307] RPC server started. Bound to: 127.4.112.254:37399
I20260812 06:18:43.715197  5009 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.4.112.254:37399 every 8 connection(s)
I20260812 06:18:43.715742  5010 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:43.717455  5010 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 3300acf161ed477fb58579d993da6f57: Bootstrap starting.
I20260812 06:18:43.718215  5010 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 3300acf161ed477fb58579d993da6f57: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:43.719168  5010 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 3300acf161ed477fb58579d993da6f57: No bootstrap required, opened a new log
I20260812 06:18:43.719522  5010 raft_consensus.cc:359] T 00000000000000000000000000000000 P 3300acf161ed477fb58579d993da6f57 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3300acf161ed477fb58579d993da6f57" member_type: VOTER }
I20260812 06:18:43.719607  5010 raft_consensus.cc:385] T 00000000000000000000000000000000 P 3300acf161ed477fb58579d993da6f57 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:43.719635  5010 raft_consensus.cc:740] T 00000000000000000000000000000000 P 3300acf161ed477fb58579d993da6f57 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 3300acf161ed477fb58579d993da6f57, State: Initialized, Role: FOLLOWER
I20260812 06:18:43.719748  5010 consensus_queue.cc:260] T 00000000000000000000000000000000 P 3300acf161ed477fb58579d993da6f57 [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: "3300acf161ed477fb58579d993da6f57" member_type: VOTER }
I20260812 06:18:43.719805  5010 raft_consensus.cc:399] T 00000000000000000000000000000000 P 3300acf161ed477fb58579d993da6f57 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:43.719831  5010 raft_consensus.cc:493] T 00000000000000000000000000000000 P 3300acf161ed477fb58579d993da6f57 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:43.719864  5010 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 3300acf161ed477fb58579d993da6f57 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:43.720480  5010 raft_consensus.cc:515] T 00000000000000000000000000000000 P 3300acf161ed477fb58579d993da6f57 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3300acf161ed477fb58579d993da6f57" member_type: VOTER }
I20260812 06:18:43.720598  5010 leader_election.cc:304] T 00000000000000000000000000000000 P 3300acf161ed477fb58579d993da6f57 [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: 3300acf161ed477fb58579d993da6f57; no voters: 
I20260812 06:18:43.720746  5010 leader_election.cc:290] T 00000000000000000000000000000000 P 3300acf161ed477fb58579d993da6f57 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:43.720858  5019 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 3300acf161ed477fb58579d993da6f57 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:43.721037  5019 raft_consensus.cc:697] T 00000000000000000000000000000000 P 3300acf161ed477fb58579d993da6f57 [term 1 LEADER]: Becoming Leader. State: Replica: 3300acf161ed477fb58579d993da6f57, State: Running, Role: LEADER
I20260812 06:18:43.721167  5010 sys_catalog.cc:565] T 00000000000000000000000000000000 P 3300acf161ed477fb58579d993da6f57 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:43.721174  5019 consensus_queue.cc:237] T 00000000000000000000000000000000 P 3300acf161ed477fb58579d993da6f57 [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: "3300acf161ed477fb58579d993da6f57" member_type: VOTER }
I20260812 06:18:43.721621  5020 sys_catalog.cc:455] T 00000000000000000000000000000000 P 3300acf161ed477fb58579d993da6f57 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "3300acf161ed477fb58579d993da6f57" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3300acf161ed477fb58579d993da6f57" member_type: VOTER } }
I20260812 06:18:43.721778  5020 sys_catalog.cc:458] T 00000000000000000000000000000000 P 3300acf161ed477fb58579d993da6f57 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:43.721740  5021 sys_catalog.cc:455] T 00000000000000000000000000000000 P 3300acf161ed477fb58579d993da6f57 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 3300acf161ed477fb58579d993da6f57. Latest consensus state: current_term: 1 leader_uuid: "3300acf161ed477fb58579d993da6f57" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3300acf161ed477fb58579d993da6f57" member_type: VOTER } }
I20260812 06:18:43.721989  5021 sys_catalog.cc:458] T 00000000000000000000000000000000 P 3300acf161ed477fb58579d993da6f57 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:43.722460  5037 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:43.723097  5037 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:43.723296  4547 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:43.724789  5037 catalog_manager.cc:1383] Generated new cluster ID: 103b5036599743c5b081ef58b3205540
I20260812 06:18:43.724846  5037 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:43.744611  5037 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:43.745149  5037 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:43.753489  5037 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 3300acf161ed477fb58579d993da6f57: Generated new TSK 0
I20260812 06:18:43.753660  5037 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:43.755518  4547 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:43.757767  5052 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:43.757870  4547 server_base.cc:1061] running on GCE node
W20260812 06:18:43.757882  5051 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:43.757982  5054 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:43.758370  4547 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:43.758424  4547 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:43.758445  4547 hybrid_clock.cc:648] HybridClock initialized: now 1786515523758444 us; error 0 us; skew 500 ppm
I20260812 06:18:43.759280  4547 webserver.cc:533] Webserver started at http://127.4.112.193:34993/ using document root <none> and password file <none>
I20260812 06:18:43.759408  4547 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:43.759446  4547 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:43.759500  4547 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:43.759825  4547 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root/instance:
uuid: "676713995ef54580b1ee4a0e5e5cb653"
format_stamp: "Formatted at 2026-08-12 06:18:43 on dist-test-slave-4tdj"
I20260812 06:18:43.761119  4547 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:43.761929  5067 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:43.762133  4547 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:43.762197  4547 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root
uuid: "676713995ef54580b1ee4a0e5e5cb653"
format_stamp: "Formatted at 2026-08-12 06:18:43 on dist-test-slave-4tdj"
I20260812 06:18:43.762269  4547 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-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:43.769639  4547 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:43.769975  4547 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:43.770227  4547 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:43.770694  4547 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:43.770732  4547 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:43.770777  4547 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:43.770803  4547 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:43.774729  4547 rpc_server.cc:307] RPC server started. Bound to: 127.4.112.193:46043
I20260812 06:18:43.775501  5197 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.4.112.193:46043 every 8 connection(s)
I20260812 06:18:43.785579  5198 heartbeater.cc:344] Connected to a master server at 127.4.112.254:37399
I20260812 06:18:43.785681  5198 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:43.785882  5198 heartbeater.cc:507] Master 127.4.112.254:37399 requested a full tablet report, sending...
I20260812 06:18:43.786500  4935 ts_manager.cc:194] Registered new tserver with Master: 676713995ef54580b1ee4a0e5e5cb653 (127.4.112.193:46043)
I20260812 06:18:43.787168  4935 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:36450
I20260812 06:18:43.787320  4547 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011989563s
I20260812 06:18:43.793702  4935 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:36460:
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:43.801801  5125 tablet_service.cc:1511] Processing CreateTablet for tablet c7385d180c684538a98f0854f36119d9 (DEFAULT_TABLE table=heavy-update-compaction-test [id=8a91b9024bbb4422800de929a74e4687]), partition=
I20260812 06:18:43.802062  5125 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet c7385d180c684538a98f0854f36119d9. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:43.804088  5222 tablet_bootstrap.cc:492] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Bootstrap starting.
I20260812 06:18:43.804926  5222 tablet_bootstrap.cc:654] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:43.805860  5222 tablet_bootstrap.cc:492] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: No bootstrap required, opened a new log
I20260812 06:18:43.805938  5222 ts_tablet_manager.cc:1403] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:43.806353  5222 raft_consensus.cc:359] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "676713995ef54580b1ee4a0e5e5cb653" member_type: VOTER last_known_addr { host: "127.4.112.193" port: 46043 } }
I20260812 06:18:43.806442  5222 raft_consensus.cc:385] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:43.806468  5222 raft_consensus.cc:740] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 676713995ef54580b1ee4a0e5e5cb653, State: Initialized, Role: FOLLOWER
I20260812 06:18:43.806564  5222 consensus_queue.cc:260] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653 [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: "676713995ef54580b1ee4a0e5e5cb653" member_type: VOTER last_known_addr { host: "127.4.112.193" port: 46043 } }
I20260812 06:18:43.806620  5222 raft_consensus.cc:399] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:43.806645  5222 raft_consensus.cc:493] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:43.806679  5222 raft_consensus.cc:3060] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:43.807520  5222 raft_consensus.cc:515] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "676713995ef54580b1ee4a0e5e5cb653" member_type: VOTER last_known_addr { host: "127.4.112.193" port: 46043 } }
I20260812 06:18:43.807636  5222 leader_election.cc:304] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653 [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: 676713995ef54580b1ee4a0e5e5cb653; no voters: 
I20260812 06:18:43.807785  5222 leader_election.cc:290] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:43.807912  5224 raft_consensus.cc:2804] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:43.808085  5222 ts_tablet_manager.cc:1434] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:43.808133  5198 heartbeater.cc:499] Master 127.4.112.254:37399 was elected leader, sending a full tablet report...
I20260812 06:18:43.808127  5224 raft_consensus.cc:697] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653 [term 1 LEADER]: Becoming Leader. State: Replica: 676713995ef54580b1ee4a0e5e5cb653, State: Running, Role: LEADER
I20260812 06:18:43.808414  5224 consensus_queue.cc:237] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653 [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: "676713995ef54580b1ee4a0e5e5cb653" member_type: VOTER last_known_addr { host: "127.4.112.193" port: 46043 } }
I20260812 06:18:43.809615  4935 catalog_manager.cc:5719] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653 reported cstate change: term changed from 0 to 1, leader changed from <none> to 676713995ef54580b1ee4a0e5e5cb653 (127.4.112.193). New cstate: current_term: 1 leader_uuid: "676713995ef54580b1ee4a0e5e5cb653" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "676713995ef54580b1ee4a0e5e5cb653" member_type: VOTER last_known_addr { host: "127.4.112.193" port: 46043 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:43.863654  4547 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.051s	user 0.008s	sys 0.014s
I20260812 06:18:44.025843  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushMRSOp(c7385d180c684538a98f0854f36119d9): perf score=23.023690
I20260812 06:18:44.186474  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushMRSOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.160s	user 0.130s	sys 0.027s Metrics: {"bytes_written":12307491,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":166,"dirs.run_wall_time_us":841,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43757,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1500}
I20260812 06:18:44.187144  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling LogGCOp(c7385d180c684538a98f0854f36119d9): free 20743880 bytes of WAL
I20260812 06:18:44.187364  5077 log_reader.cc:385] T c7385d180c684538a98f0854f36119d9: removed 2 log segments from log reader
I20260812 06:18:44.187408  5077 log.cc:1079] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/c7385d180c684538a98f0854f36119d9/wal-000000001 (ops 1-6)
I20260812 06:18:44.187440  5077 log.cc:1079] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/c7385d180c684538a98f0854f36119d9/wal-000000002 (ops 7-11)
I20260812 06:18:44.191077  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: LogGCOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.004s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:44.191375  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling UndoDeltaBlockGCOp(c7385d180c684538a98f0854f36119d9): 20513816 bytes on disk
I20260812 06:18:44.191742  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: UndoDeltaBlockGCOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:18:44.192088  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=2.188937
I20260812 06:18:44.211078  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.019s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4753,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.211612  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling MajorDeltaCompactionOp(c7385d180c684538a98f0854f36119d9): perf score=1.000000
I20260812 06:18:44.360731  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: MajorDeltaCompactionOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.149s	user 0.093s	sys 0.055s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":420,"lbm_read_time_us":9992,"lbm_reads_lt_1ms":460,"lbm_write_time_us":26160,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"thread_start_us":292,"threads_started":5,"update_count":2000}
I20260812 06:18:44.361294  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=14.095187
I20260812 06:18:44.419808  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.058s	user 0.034s	sys 0.012s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":21549,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:44.420274  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=2.188937
I20260812 06:18:44.430492  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.010s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3806,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.430927  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling MajorDeltaCompactionOp(c7385d180c684538a98f0854f36119d9): perf score=1.000000
I20260812 06:18:44.601739  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: MajorDeltaCompactionOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.171s	user 0.108s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":768,"lbm_read_time_us":13415,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27461,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2500}
I20260812 06:18:44.602233  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=14.095187
I20260812 06:18:44.654220  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.052s	user 0.023s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17093,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:44.654981  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=2.188937
I20260812 06:18:44.665288  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3843,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.665798  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling MajorDeltaCompactionOp(c7385d180c684538a98f0854f36119d9): perf score=1.000000
I20260812 06:18:44.855500  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: MajorDeltaCompactionOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.189s	user 0.125s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":314,"lbm_read_time_us":14525,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28906,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11904,"update_count":2500}
I20260812 06:18:44.855969  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=14.095187
I20260812 06:18:44.920578  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.064s	user 0.039s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22136,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:44.921164  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=2.188937
I20260812 06:18:44.931679  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3995,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.932093  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling MajorDeltaCompactionOp(c7385d180c684538a98f0854f36119d9): perf score=1.000000
I20260812 06:18:45.102990  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: MajorDeltaCompactionOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.171s	user 0.107s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":170,"lbm_read_time_us":12133,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28236,"lbm_writes_lt_1ms":543,"mutex_wait_us":30,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2500}
I20260812 06:18:45.103474  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=11.118625
I20260812 06:18:45.133205  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.030s	user 0.014s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12551,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:45.133671  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=2.188937
I20260812 06:18:45.147003  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.013s	user 0.005s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4835,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:45.147686  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling MajorDeltaCompactionOp(c7385d180c684538a98f0854f36119d9): perf score=1.000000
I20260812 06:18:45.281636  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: MajorDeltaCompactionOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.134s	user 0.081s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":607,"lbm_read_time_us":10165,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23012,"lbm_writes_lt_1ms":443,"mutex_wait_us":275,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":2000}
I20260812 06:18:45.282265  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=10.126437
I20260812 06:18:45.315899  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.033s	user 0.014s	sys 0.016s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":12702,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:45.316434  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=2.188937
I20260812 06:18:45.332355  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.016s	user 0.013s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6033,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.332880  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling MajorDeltaCompactionOp(c7385d180c684538a98f0854f36119d9): perf score=1.000000
I20260812 06:18:45.450038  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: MajorDeltaCompactionOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.117s	user 0.087s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713274,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":259,"lbm_read_time_us":7753,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23204,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2000}
I20260812 06:18:45.450589  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=10.126437
I20260812 06:18:45.488168  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.037s	user 0.014s	sys 0.018s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14504,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:45.488662  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=2.188937
I20260812 06:18:45.498485  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.010s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3529,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.498910  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushMRSOp(c7385d180c684538a98f0854f36119d9): perf score=1.000000
I20260812 06:18:45.528266  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushMRSOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.029s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":198,"dirs.run_wall_time_us":1434,"drs_written":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1506,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:45.528908  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling LogGCOp(c7385d180c684538a98f0854f36119d9): free 124710290 bytes of WAL
I20260812 06:18:45.529170  5077 log_reader.cc:385] T c7385d180c684538a98f0854f36119d9: removed 12 log segments from log reader
I20260812 06:18:45.529222  5077 log.cc:1079] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/c7385d180c684538a98f0854f36119d9/wal-000000003 (ops 12-16)
I20260812 06:18:45.529263  5077 log.cc:1079] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/c7385d180c684538a98f0854f36119d9/wal-000000004 (ops 17-21)
I20260812 06:18:45.529295  5077 log.cc:1079] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/c7385d180c684538a98f0854f36119d9/wal-000000005 (ops 22-26)
I20260812 06:18:45.529321  5077 log.cc:1079] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/c7385d180c684538a98f0854f36119d9/wal-000000006 (ops 27-31)
I20260812 06:18:45.529352  5077 log.cc:1079] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/c7385d180c684538a98f0854f36119d9/wal-000000007 (ops 32-36)
I20260812 06:18:45.529382  5077 log.cc:1079] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/c7385d180c684538a98f0854f36119d9/wal-000000008 (ops 37-41)
I20260812 06:18:45.529414  5077 log.cc:1079] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/c7385d180c684538a98f0854f36119d9/wal-000000009 (ops 42-46)
I20260812 06:18:45.529446  5077 log.cc:1079] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/c7385d180c684538a98f0854f36119d9/wal-000000010 (ops 47-51)
I20260812 06:18:45.529476  5077 log.cc:1079] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/c7385d180c684538a98f0854f36119d9/wal-000000011 (ops 52-56)
I20260812 06:18:45.529507  5077 log.cc:1079] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/c7385d180c684538a98f0854f36119d9/wal-000000012 (ops 57-61)
I20260812 06:18:45.529537  5077 log.cc:1079] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/c7385d180c684538a98f0854f36119d9/wal-000000013 (ops 62-66)
I20260812 06:18:45.529568  5077 log.cc:1079] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/c7385d180c684538a98f0854f36119d9/wal-000000014 (ops 67-71)
I20260812 06:18:45.552922  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: LogGCOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.024s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:18:45.553335  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling UndoDeltaBlockGCOp(c7385d180c684538a98f0854f36119d9): 482 bytes on disk
I20260812 06:18:45.553750  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: UndoDeltaBlockGCOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:18:45.554245  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=3.181125
I20260812 06:18:45.566038  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4166,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:45.566473  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling LogGCOp(c7385d180c684538a98f0854f36119d9): free 12017932 bytes of WAL
I20260812 06:18:45.566664  5077 log_reader.cc:385] T c7385d180c684538a98f0854f36119d9: removed 1 log segments from log reader
I20260812 06:18:45.566732  5077 log.cc:1079] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/c7385d180c684538a98f0854f36119d9/wal-000000015 (ops 72-76)
I20260812 06:18:45.569458  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: LogGCOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:45.569738  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=2.188937
I20260812 06:18:45.579303  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3218,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:45.579733  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling MajorDeltaCompactionOp(c7385d180c684538a98f0854f36119d9): perf score=1.000000
I20260812 06:18:45.750003  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: MajorDeltaCompactionOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.170s	user 0.140s	sys 0.027s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918323,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2413,"lbm_read_time_us":13236,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33933,"lbm_writes_lt_1ms":643,"mutex_wait_us":2167,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3712,"thread_start_us":76,"threads_started":1,"update_count":3000}
I20260812 06:18:45.750566  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=14.095187
I20260812 06:18:45.799058  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.048s	user 0.032s	sys 0.012s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19489,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.799549  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=2.188937
I20260812 06:18:45.809792  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3782,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.810364  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling MajorDeltaCompactionOp(c7385d180c684538a98f0854f36119d9): perf score=1.000000
I20260812 06:18:45.958163  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: MajorDeltaCompactionOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.148s	user 0.124s	sys 0.013s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":124,"lbm_read_time_us":11501,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26792,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8192,"update_count":2500}
I20260812 06:18:45.958827  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=11.118625
I20260812 06:18:45.997021  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.038s	user 0.019s	sys 0.016s Metrics: {"bytes_written":12717742,"delete_count":0,"lbm_write_time_us":16771,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:45.997534  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=2.188937
I20260812 06:18:46.009526  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4370,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:46.010012  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling MajorDeltaCompactionOp(c7385d180c684538a98f0854f36119d9): perf score=1.000000
I20260812 06:18:46.158720  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: MajorDeltaCompactionOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.149s	user 0.116s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713270,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":448,"lbm_read_time_us":10931,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21943,"lbm_writes_lt_1ms":443,"mutex_wait_us":65,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14208,"update_count":2000}
I20260812 06:18:46.159245  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=11.118625
I20260812 06:18:46.202178  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.043s	user 0.015s	sys 0.024s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":14096,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:46.202859  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=2.188937
I20260812 06:18:46.216619  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5043,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":450}
I20260812 06:18:46.217133  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling MajorDeltaCompactionOp(c7385d180c684538a98f0854f36119d9): perf score=1.000000
I20260812 06:18:46.366683  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: MajorDeltaCompactionOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.149s	user 0.091s	sys 0.058s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713264,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":830,"lbm_read_time_us":10743,"lbm_reads_lt_1ms":468,"lbm_write_time_us":23678,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7680,"update_count":2000}
I20260812 06:18:46.367267  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=11.118625
I20260812 06:18:46.405550  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.038s	user 0.029s	sys 0.005s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16371,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:46.406025  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=2.188937
I20260812 06:18:46.416942  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3975,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:46.417493  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling MajorDeltaCompactionOp(c7385d180c684538a98f0854f36119d9): perf score=1.000000
I20260812 06:18:46.540256  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: MajorDeltaCompactionOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.123s	user 0.106s	sys 0.015s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":963,"lbm_read_time_us":8496,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23301,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2000}
I20260812 06:18:46.540858  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=10.126437
I20260812 06:18:46.581058  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.040s	user 0.027s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14334,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:46.581641  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=2.188937
I20260812 06:18:46.596992  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5472,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.597599  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling MajorDeltaCompactionOp(c7385d180c684538a98f0854f36119d9): perf score=1.000000
I20260812 06:18:46.718761  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: MajorDeltaCompactionOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.121s	user 0.080s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":659,"lbm_read_time_us":8442,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24089,"lbm_writes_lt_1ms":443,"mutex_wait_us":303,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:46.719290  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=10.126437
I20260812 06:18:46.763433  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.044s	user 0.025s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13444,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:46.763991  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=2.188937
I20260812 06:18:46.774049  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3735,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.774670  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling MajorDeltaCompactionOp(c7385d180c684538a98f0854f36119d9): perf score=1.000000
I20260812 06:18:46.916653  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: MajorDeltaCompactionOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.142s	user 0.078s	sys 0.062s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1248,"lbm_read_time_us":10390,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21482,"lbm_writes_lt_1ms":443,"mutex_wait_us":545,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:46.917249  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=10.126437
I20260812 06:18:46.950428  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.033s	user 0.018s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12797,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:46.950902  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=2.188937
I20260812 06:18:46.962775  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4306,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.963358  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushMRSOp(c7385d180c684538a98f0854f36119d9): perf score=1.000000
I20260812 06:18:46.989174  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushMRSOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.026s	user 0.024s	sys 0.000s Metrics: {"bytes_written":1316415,"cfile_init":1,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":186,"dirs.run_wall_time_us":1353,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1405,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:46.990069  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling LogGCOp(c7385d180c684538a98f0854f36119d9): free 121006462 bytes of WAL
I20260812 06:18:46.990345  5077 log_reader.cc:385] T c7385d180c684538a98f0854f36119d9: removed 12 log segments from log reader
I20260812 06:18:46.990391  5077 log.cc:1079] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/c7385d180c684538a98f0854f36119d9/wal-000000016 (ops 77-81)
I20260812 06:18:46.990429  5077 log.cc:1079] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/c7385d180c684538a98f0854f36119d9/wal-000000017 (ops 82-86)
I20260812 06:18:46.990463  5077 log.cc:1079] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/c7385d180c684538a98f0854f36119d9/wal-000000018 (ops 87-91)
I20260812 06:18:46.990494  5077 log.cc:1079] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/c7385d180c684538a98f0854f36119d9/wal-000000019 (ops 92-96)
I20260812 06:18:46.990526  5077 log.cc:1079] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/c7385d180c684538a98f0854f36119d9/wal-000000020 (ops 97-101)
I20260812 06:18:46.990557  5077 log.cc:1079] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/c7385d180c684538a98f0854f36119d9/wal-000000021 (ops 102-106)
I20260812 06:18:46.990588  5077 log.cc:1079] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/c7385d180c684538a98f0854f36119d9/wal-000000022 (ops 107-110)
I20260812 06:18:46.990619  5077 log.cc:1079] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/c7385d180c684538a98f0854f36119d9/wal-000000023 (ops 111-115)
I20260812 06:18:46.990649  5077 log.cc:1079] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/c7385d180c684538a98f0854f36119d9/wal-000000024 (ops 116-120)
I20260812 06:18:46.990688  5077 log.cc:1079] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/c7385d180c684538a98f0854f36119d9/wal-000000025 (ops 121-125)
I20260812 06:18:46.990720  5077 log.cc:1079] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/c7385d180c684538a98f0854f36119d9/wal-000000026 (ops 126-130)
I20260812 06:18:46.990751  5077 log.cc:1079] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/c7385d180c684538a98f0854f36119d9/wal-000000027 (ops 131-135)
I20260812 06:18:47.014458  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: LogGCOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.024s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:18:47.014967  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling UndoDeltaBlockGCOp(c7385d180c684538a98f0854f36119d9): 492 bytes on disk
I20260812 06:18:47.015540  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: UndoDeltaBlockGCOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4}
I20260812 06:18:47.016067  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=5.165500
I20260812 06:18:47.042897  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.027s	user 0.019s	sys 0.007s Metrics: {"bytes_written":7302546,"delete_count":0,"lbm_write_time_us":7990,"lbm_writes_lt_1ms":181,"mutex_wait_us":159,"reinsert_count":0,"update_count":890}
I20260812 06:18:47.043380  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling MajorDeltaCompactionOp(c7385d180c684538a98f0854f36119d9): perf score=1.000000
I20260812 06:18:47.234167  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: MajorDeltaCompactionOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.191s	user 0.140s	sys 0.049s Metrics: {"cfile_cache_miss":611,"cfile_cache_miss_bytes":28015683,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":2476,"lbm_read_time_us":14680,"lbm_reads_lt_1ms":647,"lbm_write_time_us":29814,"lbm_writes_lt_1ms":621,"mutex_wait_us":1965,"peak_mem_usage":72558934,"reinsert_count":0,"spinlock_wait_cycles":5120,"thread_start_us":78,"threads_started":1,"update_count":2890}
I20260812 06:18:47.235500  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=15.087375
I20260812 06:18:47.287778  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.052s	user 0.029s	sys 0.022s Metrics: {"bytes_written":17312441,"delete_count":0,"lbm_write_time_us":18683,"lbm_writes_lt_1ms":425,"reinsert_count":0,"update_count":2110}
I20260812 06:18:47.288255  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling LogGCOp(c7385d180c684538a98f0854f36119d9): free 12017954 bytes of WAL
I20260812 06:18:47.288502  5077 log_reader.cc:385] T c7385d180c684538a98f0854f36119d9: removed 1 log segments from log reader
I20260812 06:18:47.288548  5077 log.cc:1079] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/c7385d180c684538a98f0854f36119d9/wal-000000028 (ops 136-140)
I20260812 06:18:47.290619  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: LogGCOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.002s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:47.290926  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=2.188937
I20260812 06:18:47.302017  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.011s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4174,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.303606  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling MajorDeltaCompactionOp(c7385d180c684538a98f0854f36119d9): perf score=1.000000
I20260812 06:18:47.469499  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: MajorDeltaCompactionOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.166s	user 0.121s	sys 0.044s Metrics: {"cfile_cache_miss":554,"cfile_cache_miss_bytes":25718223,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":511,"lbm_read_time_us":11164,"lbm_reads_lt_1ms":594,"lbm_write_time_us":27972,"lbm_writes_lt_1ms":565,"mutex_wait_us":39,"peak_mem_usage":65059054,"reinsert_count":0,"spinlock_wait_cycles":607616,"update_count":2610}
I20260812 06:18:47.469933  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=14.095187
I20260812 06:18:47.520706  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.051s	user 0.025s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22978,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:47.521499  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=2.188937
I20260812 06:18:47.541751  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.020s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5124,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.542248  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling MajorDeltaCompactionOp(c7385d180c684538a98f0854f36119d9): perf score=1.000000
I20260812 06:18:47.706740  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: MajorDeltaCompactionOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.164s	user 0.111s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":833,"lbm_read_time_us":11468,"lbm_reads_lt_1ms":564,"lbm_write_time_us":26353,"lbm_writes_lt_1ms":543,"mutex_wait_us":315,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:47.707224  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=14.095187
I20260812 06:18:47.763540  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.056s	user 0.027s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24028,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:47.764070  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=3.181125
I20260812 06:18:47.797525  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.033s	user 0.013s	sys 0.010s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6590,"lbm_writes_lt_1ms":113,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":550}
I20260812 06:18:47.798103  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=2.188937
I20260812 06:18:47.809082  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4040,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:47.809645  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling MajorDeltaCompactionOp(c7385d180c684538a98f0854f36119d9): perf score=1.000000
I20260812 06:18:48.009172  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: MajorDeltaCompactionOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.199s	user 0.123s	sys 0.076s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918204,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":867,"lbm_read_time_us":15284,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33672,"lbm_writes_lt_1ms":643,"mutex_wait_us":263,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":3000}
I20260812 06:18:48.009713  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=14.095187
I20260812 06:18:48.071154  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.061s	user 0.027s	sys 0.032s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22422,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:48.071712  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=2.188937
I20260812 06:18:48.087502  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5438,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.088063  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling MajorDeltaCompactionOp(c7385d180c684538a98f0854f36119d9): perf score=1.000000
I20260812 06:18:48.251192  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: MajorDeltaCompactionOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.163s	user 0.107s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1014,"lbm_read_time_us":11022,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27017,"lbm_writes_lt_1ms":543,"mutex_wait_us":548,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:48.251765  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=14.095187
I20260812 06:18:48.311460  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.060s	user 0.026s	sys 0.032s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":21585,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:48.311931  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=3.181125
I20260812 06:18:48.336040  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.024s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4198,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:48.336545  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=2.188937
I20260812 06:18:48.349628  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4838,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:48.350154  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushMRSOp(c7385d180c684538a98f0854f36119d9): perf score=1.000000
I20260812 06:18:48.384406  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushMRSOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.034s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":207,"dirs.run_wall_time_us":1275,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1283,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:48.385054  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling LogGCOp(c7385d180c684538a98f0854f36119d9): free 108535690 bytes of WAL
I20260812 06:18:48.385298  5077 log_reader.cc:385] T c7385d180c684538a98f0854f36119d9: removed 11 log segments from log reader
I20260812 06:18:48.385345  5077 log.cc:1079] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/c7385d180c684538a98f0854f36119d9/wal-000000029 (ops 141-145)
I20260812 06:18:48.385375  5077 log.cc:1079] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/c7385d180c684538a98f0854f36119d9/wal-000000030 (ops 146-150)
I20260812 06:18:48.385416  5077 log.cc:1079] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/c7385d180c684538a98f0854f36119d9/wal-000000031 (ops 151-154)
I20260812 06:18:48.385449  5077 log.cc:1079] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/c7385d180c684538a98f0854f36119d9/wal-000000032 (ops 155-159)
I20260812 06:18:48.385483  5077 log.cc:1079] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/c7385d180c684538a98f0854f36119d9/wal-000000033 (ops 160-164)
I20260812 06:18:48.385516  5077 log.cc:1079] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/c7385d180c684538a98f0854f36119d9/wal-000000034 (ops 165-168)
I20260812 06:18:48.385550  5077 log.cc:1079] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/c7385d180c684538a98f0854f36119d9/wal-000000035 (ops 169-173)
I20260812 06:18:48.385582  5077 log.cc:1079] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/c7385d180c684538a98f0854f36119d9/wal-000000036 (ops 174-178)
I20260812 06:18:48.385614  5077 log.cc:1079] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/c7385d180c684538a98f0854f36119d9/wal-000000037 (ops 179-183)
I20260812 06:18:48.385646  5077 log.cc:1079] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/c7385d180c684538a98f0854f36119d9/wal-000000038 (ops 184-188)
I20260812 06:18:48.385679  5077 log.cc:1079] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: Deleting log segment in path: /tmp/dist-test-taskeq5FUT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515518483989-4547-0/minicluster-data/ts-0-root/wals/c7385d180c684538a98f0854f36119d9/wal-000000039 (ops 189-193)
I20260812 06:18:48.406482  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: LogGCOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.021s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:18:48.406919  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling UndoDeltaBlockGCOp(c7385d180c684538a98f0854f36119d9): 448 bytes on disk
I20260812 06:18:48.407330  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: UndoDeltaBlockGCOp(c7385d180c684538a98f0854f36119d9) 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:18:48.407867  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=3.181125
I20260812 06:18:48.424650  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.017s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4021,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:48.425084  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9): perf score=2.188937
I20260812 06:18:48.434728  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: FlushDeltaMemStoresOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.009s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3427,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:48.435169  5202 maintenance_manager.cc:419] P 676713995ef54580b1ee4a0e5e5cb653: Scheduling MajorDeltaCompactionOp(c7385d180c684538a98f0854f36119d9): perf score=1.000000
I20260812 06:18:48.518867  4547 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.655s	user 1.678s	sys 0.146s
I20260812 06:18:48.633513  4547 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.114s	user 0.001s	sys 0.000s
I20260812 06:18:48.634071  4547 tablet_server.cc:179] TabletServer@127.4.112.193:0 shutting down...
I20260812 06:18:48.669322  5077 maintenance_manager.cc:643] P 676713995ef54580b1ee4a0e5e5cb653: MajorDeltaCompactionOp(c7385d180c684538a98f0854f36119d9) complete. Timing: real 0.234s	user 0.134s	sys 0.100s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37123258,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1442,"lbm_read_time_us":16644,"lbm_reads_lt_1ms":871,"lbm_write_time_us":36581,"lbm_writes_lt_1ms":843,"mutex_wait_us":320,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":10368,"thread_start_us":89,"threads_started":1,"update_count":4000}
I20260812 06:18:48.669955  4547 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:48.670280  4547 tablet_replica.cc:333] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653: stopping tablet replica
I20260812 06:18:48.670477  4547 raft_consensus.cc:2243] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:48.670693  4547 raft_consensus.cc:2272] T c7385d180c684538a98f0854f36119d9 P 676713995ef54580b1ee4a0e5e5cb653 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:48.675345  4547 tablet_server.cc:196] TabletServer@127.4.112.193:0 shutdown complete.
I20260812 06:18:48.740543  4547 master.cc:562] Master@127.4.112.254:37399 shutting down...
I20260812 06:18:48.743520  4547 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 3300acf161ed477fb58579d993da6f57 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:48.743678  4547 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 3300acf161ed477fb58579d993da6f57 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:48.743746  4547 tablet_replica.cc:333] T 00000000000000000000000000000000 P 3300acf161ed477fb58579d993da6f57: stopping tablet replica
I20260812 06:18:48.755730  4547 master.cc:584] Master@127.4.112.254:37399 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5148 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10335 ms total)

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